# Checking port 65410
# Found port 65410
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=65410 host=/tmp/qWQuQEaj3q
Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log
[07:49:38.369](0.015s) # 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 25349
# 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/qWQuQEaj3q -p 65410 --checkpoint fast --no-sync
# Backup finished
# Checking port 65411
# Found port 65411
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=65411 host=/tmp/qWQuQEaj3q
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 25584
### 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 25614
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:49:41.304 UTC [25676][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-10 07:49:41.304 UTC [25676][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:41.317 UTC [25684][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:41 UTC
2024-03-10 07:49:41.318 UTC [25684][startup] LOG:  entering standby mode
2024-03-10 07:49:41.319 UTC [25684][startup] LOG:  consistent recovery state reached at 0/30000A0
2024-03-10 07:49:41.319 UTC [25676][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:41.319 UTC [25684][startup] LOG:  invalid record length at 0/30000A0: expected at least 24, got 0
2024-03-10 07:49:41.331 UTC [25686][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:41.331 UTC [25684][startup] LOG:  redo starts at 0/30000A0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:41.376 UTC [25691][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:41.377 UTC [25691][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-10 07:49:41.377 UTC [25691][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:41.401 UTC [25691][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:41.402 UTC [25691][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:41.403 UTC [25691][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-10 07:49:41.404 UTC [25691][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-10 07:49:41.415 UTC [25691][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.047 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: error: publisher requires 3 replication slots, but only 2 remain
pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 4.
[07:49:41.614](3.244s) 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-10 07:49:41.653 UTC [25686][walreceiver] LOG:  replication terminated by primary server
2024-03-10 07:49:41.653 UTC [25686][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3004628.
2024-03-10 07:49:41.653 UTC [25686][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-10 07:49:41.657 UTC [25684][startup] LOG:  invalid record length at 0/3004628: expected at least 24, got 0
2024-03-10 07:49:41.670 UTC [25712][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:49:41.670 UTC [25684][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 25720
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-10 07:49:41.954 UTC [25676][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:41.954 UTC [25676][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:41.958 UTC [25682][checkpointer] LOG:  shutting down
2024-03-10 07:49:41.958 UTC [25682][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-10 07:49:41.959 UTC [25682][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-10 07:49:41.959 UTC [25682][checkpointer] LOG:  recovery restart point at 0/30045B0
2024-03-10 07:49:41.963 UTC [25676][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-10 07:49:42.195 UTC [25774][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-10 07:49:42.195 UTC [25774][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:42.225 UTC [25784][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:41 UTC
2024-03-10 07:49:42.225 UTC [25784][startup] LOG:  entering standby mode
2024-03-10 07:49:42.226 UTC [25784][startup] LOG:  consistent recovery state reached at 0/3004628
2024-03-10 07:49:42.226 UTC [25784][startup] LOG:  invalid record length at 0/3004628: expected at least 24, got 0
2024-03-10 07:49:42.227 UTC [25774][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:42.252 UTC [25787][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:42.256 UTC [25792][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:42.256 UTC [25792][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-10 07:49:42.256 UTC [25792][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:42.273 UTC [25792][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:42.274 UTC [25792][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:42.274 UTC [25792][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-10 07:49:42.275 UTC [25792][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-10 07:49:42.281 UTC [25792][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.029 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_25738" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_25738" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_25738" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_25738" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:49:42.421 UTC [25774][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:42.421 UTC [25774][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:42.425 UTC [25787][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:42.433 UTC [25782][checkpointer] LOG:  shutting down
2024-03-10 07:49:42.437 UTC [25774][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:49:42.552 UTC [25829][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-10 07:49:42.552 UTC [25829][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:42.568 UTC [25837][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:42 UTC
2024-03-10 07:49:42.568 UTC [25837][startup] LOG:  entering standby mode
2024-03-10 07:49:42.570 UTC [25837][startup] LOG:  consistent recovery state reached at 0/3004628
2024-03-10 07:49:42.570 UTC [25837][startup] LOG:  invalid record length at 0/3004628: expected at least 24, got 0
2024-03-10 07:49:42.570 UTC [25829][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:42.592 UTC [25841][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:42.592 UTC [25837][startup] LOG:  redo starts at 0/3004628
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-10 07:49:42.626 UTC [25844][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:42.626 UTC [25844][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-10 07:49:42.626 UTC [25844][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:42.649 UTC [25844][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:42.650 UTC [25844][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-10 07:49:42.651 UTC [25844][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.026 user=postgres database=pg1 host=[local]
2024-03-10 07:49:42.681 UTC [25845][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:42.694 UTC [25845][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-10 07:49:42.694 UTC [25845][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:42.695 UTC [25845][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_25738" on database "pg1"
2024-03-10 07:49:42.696 UTC [25845][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_25738'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_25738" on database "pg1"
2024-03-10 07:49:42.701 UTC [25850][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:42.701 UTC [25850][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-10 07:49:42.701 UTC [25850][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:49:42.702 UTC [25845][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.020 user=postgres database=pg1 host=[local]
2024-03-10 07:49:42.714 UTC [25850][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_25738" on database "pg2"
2024-03-10 07:49:42.715 UTC [25850][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_25738'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_25738" on database "pg2"
2024-03-10 07:49:42.718 UTC [25850][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.017 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-10 07:49:42.752 UTC [25829][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:42.752 UTC [25829][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:42.752 UTC [25841][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:42.759 UTC [25835][checkpointer] LOG:  shutting down
2024-03-10 07:49:42.763 UTC [25829][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638815480689802 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:49:43.002 UTC [25879][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-10 07:49:43.002 UTC [25879][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:43.018 UTC [25885][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:42 UTC
2024-03-10 07:49:43.018 UTC [25885][startup] LOG:  entering standby mode
2024-03-10 07:49:43.019 UTC [25885][startup] LOG:  redo starts at 0/3004628
2024-03-10 07:49:43.019 UTC [25885][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-10 07:49:43.019 UTC [25885][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-10 07:49:43.026 UTC [25879][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-10 07:49:43.069 UTC [25886][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
[07:49:43.468](1.854s) 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-10 07:49:43.477 UTC [25879][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:43.477 UTC [25879][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:43.481 UTC [25886][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:43.485 UTC [25883][checkpointer] LOG:  shutting down
2024-03-10 07:49:43.489 UTC [25879][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 25915
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:49:43.985 UTC [25967][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-10 07:49:43.985 UTC [25967][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:43.996 UTC [25976][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:43 UTC
2024-03-10 07:49:43.996 UTC [25976][startup] LOG:  entering standby mode
2024-03-10 07:49:43.998 UTC [25976][startup] LOG:  redo starts at 0/3004628
2024-03-10 07:49:43.998 UTC [25976][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-10 07:49:43.998 UTC [25967][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:43.998 UTC [25976][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-10 07:49:44.012 UTC [25980][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-10 07:49:44.087 UTC [26028][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:44.088 UTC [26028][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-10 07:49:44.088 UTC [26028][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:44.119 UTC [26028][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:44.122 UTC [26028][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:44.126 UTC [26028][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-10 07:49:44.127 UTC [26028][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.
=================================================================
==25927==ERROR: AddressSanitizer: heap-use-after-free on address 0x61a000001458 at pc 0x7ffabf449dce bp 0x7ffc86720ce0 sp 0x7ffc86720cd8
READ of size 4 at 0x61a000001458 thread T0
2024-03-10 07:49:44.142 UTC [26028][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.055 user=postgres database=pg1 host=[local]
    #0 0x7ffabf449dcd in sendTerminateConn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502
    #1 0x7ffabf44b42e in pqClosePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4528
    #2 0x7ffabf44b59c in PQfinish /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4566
    #3 0x5566a04f1de1 in disconnect_database /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:446
    #4 0x5566a04f38cc in check_subscriber /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:950
    #5 0x5566a04f72bb in main /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:1983
    #6 0x7ffabf24ad09 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x23d09)
    #7 0x5566a04f1859 in _start (/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_createsubscriber+0xd859)

0x61a000001458 is located 472 bytes inside of 1192-byte region [0x61a000001280,0x61a000001728)
freed by thread T0 here:
    #0 0x7ffabf586b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123
    #1 0x7ffabf44af3b in freePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4406

previously allocated by thread T0 here:
    #0 0x7ffabf586e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
    #1 0x7ffabf44b080 in pqMakeEmptyPGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4263

SUMMARY: AddressSanitizer: heap-use-after-free /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502 in sendTerminateConn
Shadow bytes around the buggy address:
  0x0c347fff8230: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c347fff8240: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c347fff8250: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff8260: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff8270: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x0c347fff8280: fd fd fd fd fd fd fd fd fd fd fd[fd]fd fd fd fd
  0x0c347fff8290: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
  Shadow gap:              cc
==25927==ABORTING
[07:49:44.334](0.866s) 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
2024-03-10 07:49:44.344 UTC [25967][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:44.344 UTC [25967][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:44.344 UTC [25980][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:44.350 UTC [25974][checkpointer] LOG:  shutting down
waiting for server to shut down....2024-03-10 07:49:44.354 UTC [25967][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 26065
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:49:44.793 UTC [26104][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-10 07:49:44.793 UTC [26104][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:44.801 UTC [26108][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:44 UTC
2024-03-10 07:49:44.801 UTC [26108][startup] LOG:  entering standby mode
2024-03-10 07:49:44.803 UTC [26108][startup] LOG:  redo starts at 0/3004628
2024-03-10 07:49:44.803 UTC [26108][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-10 07:49:44.803 UTC [26104][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:44.803 UTC [26108][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-10 07:49:44.849 UTC [26110][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-10 07:49:44.887 UTC [26132][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:44.888 UTC [26132][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-10 07:49:44.888 UTC [26132][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:44.919 UTC [26132][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:44.921 UTC [26132][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:44.921 UTC [26132][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-10 07:49:44.923 UTC [26132][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-10 07:49:44.929 UTC [26132][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.042 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_26077" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_26077" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_26077" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_26077" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:49:45.198 UTC [26104][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:45.198 UTC [26104][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:45.198 UTC [26110][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:45.206 UTC [26106][checkpointer] LOG:  shutting down
2024-03-10 07:49:45.211 UTC [26104][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:49:45.601 UTC [26205][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-10 07:49:45.601 UTC [26205][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:45.636 UTC [26212][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:45 UTC
2024-03-10 07:49:45.636 UTC [26212][startup] LOG:  entering standby mode
2024-03-10 07:49:45.638 UTC [26212][startup] LOG:  redo starts at 0/3004628
2024-03-10 07:49:45.638 UTC [26212][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-10 07:49:45.638 UTC [26212][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-10 07:49:45.638 UTC [26205][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:45.675 UTC [26213][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-10 07:49:45.697 UTC [26215][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:45.698 UTC [26215][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-10 07:49:45.698 UTC [26215][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:45.794 UTC [26215][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:45.800 UTC [26215][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-10 07:49:45.802 UTC [26215][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.105 user=postgres database=pg1 host=[local]
2024-03-10 07:49:45.813 UTC [26218][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:45.814 UTC [26218][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-10 07:49:45.814 UTC [26218][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:45.825 UTC [26218][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_26077" on database "pg1"
2024-03-10 07:49:45.836 UTC [26218][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_26077'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_26077" on database "pg1"
2024-03-10 07:49:45.840 UTC [26218][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.028 user=postgres database=pg1 host=[local]
2024-03-10 07:49:45.855 UTC [26220][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:45.856 UTC [26220][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-10 07:49:45.856 UTC [26220][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:49:45.920 UTC [26220][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_26077" on database "pg2"
2024-03-10 07:49:45.923 UTC [26220][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_26077'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_26077" on database "pg2"
2024-03-10 07:49:45.932 UTC [26220][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.077 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-10 07:49:45.998 UTC [26205][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:45.998 UTC [26205][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:45.998 UTC [26213][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:46.008 UTC [26210][checkpointer] LOG:  shutting down
2024-03-10 07:49:46.012 UTC [26205][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638829575165405 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:49:46.190 UTC [26246][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-10 07:49:46.190 UTC [26246][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:46.231 UTC [26256][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:46 UTC
2024-03-10 07:49:46.231 UTC [26256][startup] LOG:  entering standby mode
2024-03-10 07:49:46.233 UTC [26256][startup] LOG:  redo starts at 0/3004628
2024-03-10 07:49:46.233 UTC [26256][startup] LOG:  consistent recovery state reached at 0/3008B38
2024-03-10 07:49:46.233 UTC [26256][startup] LOG:  invalid record length at 0/3008B38: expected at least 24, got 0
2024-03-10 07:49:46.237 UTC [26246][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:46.261 UTC [26260][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: Done!
[07:49:46.706](2.372s) 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-10 07:49:46.749 UTC [26260][walreceiver] LOG:  replication terminated by primary server
2024-03-10 07:49:46.749 UTC [26260][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008BB0.
2024-03-10 07:49:46.749 UTC [26260][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-10 07:49:46.753 UTC [26256][startup] LOG:  invalid record length at 0/3008BB0: expected at least 24, got 0
2024-03-10 07:49:46.769 UTC [26298][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:49:46.769 UTC [26256][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 26304
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-10 07:49:47.101 UTC [26246][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:47.101 UTC [26246][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:47.108 UTC [26254][checkpointer] LOG:  shutting down
2024-03-10 07:49:47.108 UTC [26254][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-10 07:49:47.108 UTC [26254][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-10 07:49:47.108 UTC [26254][checkpointer] LOG:  recovery restart point at 0/3008B38
2024-03-10 07:49:47.112 UTC [26246][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-10 07:49:47.332 UTC [26349][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-10 07:49:47.332 UTC [26349][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:47.359 UTC [26356][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:47 UTC
2024-03-10 07:49:47.361 UTC [26356][startup] LOG:  entering standby mode
2024-03-10 07:49:47.362 UTC [26356][startup] LOG:  consistent recovery state reached at 0/3008BB0
2024-03-10 07:49:47.362 UTC [26356][startup] LOG:  invalid record length at 0/3008BB0: expected at least 24, got 0
2024-03-10 07:49:47.362 UTC [26349][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:47.390 UTC [26359][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:47.391 UTC [26359][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-10 07:49:47.391 UTC [26359][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:47.392 UTC [26357][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:47.392 UTC [26356][startup] LOG:  redo starts at 0/3008BB0
2024-03-10 07:49:47.418 UTC [26359][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:47.420 UTC [26359][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:47.421 UTC [26359][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-10 07:49:47.423 UTC [26359][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-10 07:49:47.432 UTC [26359][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.042 user=postgres database=pg1 host=[local]
pg_createsubscriber: primary has replication slot "physical_slot"
pg_createsubscriber: error: publisher requires wal_level >= logical
[07:49:47.590](0.884s) 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-10 07:49:47.629 UTC [26357][walreceiver] LOG:  replication terminated by primary server
2024-03-10 07:49:47.629 UTC [26357][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008C60.
2024-03-10 07:49:47.629 UTC [26357][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-10 07:49:47.633 UTC [26356][startup] LOG:  invalid record length at 0/3008C60: expected at least 24, got 0
2024-03-10 07:49:47.649 UTC [26376][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:49:47.649 UTC [26356][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 26379
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-10 07:49:47.985 UTC [26349][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:47.985 UTC [26349][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:47.992 UTC [26354][checkpointer] LOG:  shutting down
2024-03-10 07:49:47.992 UTC [26354][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-10 07:49:47.992 UTC [26354][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-10 07:49:47.992 UTC [26354][checkpointer] LOG:  recovery restart point at 0/3008BE8
2024-03-10 07:49:47.997 UTC [26349][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-10 07:49:48.129 UTC [26409][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-10 07:49:48.129 UTC [26409][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:48.142 UTC [26415][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:47 UTC
2024-03-10 07:49:48.143 UTC [26415][startup] LOG:  entering standby mode
2024-03-10 07:49:48.144 UTC [26415][startup] LOG:  consistent recovery state reached at 0/3008C60
2024-03-10 07:49:48.144 UTC [26415][startup] LOG:  invalid record length at 0/3008C60: expected at least 24, got 0
2024-03-10 07:49:48.145 UTC [26409][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:48.181 UTC [26416][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:48.181 UTC [26415][startup] LOG:  redo starts at 0/3008C60
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:48.229 UTC [26424][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:48.229 UTC [26424][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-10 07:49:48.229 UTC [26424][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:48.276 UTC [26424][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:48.282 UTC [26424][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:48.282 UTC [26424][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-10 07:49:48.302 UTC [26424][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-10 07:49:48.315 UTC [26424][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.090 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_26388" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_26388" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_26388" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_26388" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:49:48.465 UTC [26409][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:48.466 UTC [26409][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:48.470 UTC [26416][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:48.474 UTC [26412][checkpointer] LOG:  shutting down
2024-03-10 07:49:48.478 UTC [26409][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:49:48.706 UTC [26473][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-10 07:49:48.706 UTC [26473][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:48.733 UTC [26481][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:48 UTC
2024-03-10 07:49:48.734 UTC [26481][startup] LOG:  entering standby mode
2024-03-10 07:49:48.738 UTC [26481][startup] LOG:  redo starts at 0/3008C60
2024-03-10 07:49:48.740 UTC [26481][startup] LOG:  consistent recovery state reached at 0/3008C98
2024-03-10 07:49:48.740 UTC [26473][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:48.740 UTC [26481][startup] LOG:  invalid record length at 0/3008C98: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-10 07:49:48.772 UTC [26487][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:48.772 UTC [26487][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-10 07:49:48.772 UTC [26487][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:48.777 UTC [26483][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:48.786 UTC [26487][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:48.786 UTC [26487][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-10 07:49:48.787 UTC [26487][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.016 user=postgres database=pg1 host=[local]
2024-03-10 07:49:48.807 UTC [26493][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:48.808 UTC [26493][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-10 07:49:48.808 UTC [26493][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:48.809 UTC [26493][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_26388" on database "pg1"
2024-03-10 07:49:48.810 UTC [26493][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_26388'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_26388" on database "pg1"
2024-03-10 07:49:48.813 UTC [26493][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=pg1 host=[local]
2024-03-10 07:49:48.827 UTC [26496][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:48.828 UTC [26496][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-10 07:49:48.828 UTC [26496][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:49:48.857 UTC [26496][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_26388" on database "pg2"
2024-03-10 07:49:48.857 UTC [26496][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_26388'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_26388" on database "pg2"
2024-03-10 07:49:48.864 UTC [26496][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.037 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-10 07:49:48.905 UTC [26473][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:48.905 UTC [26473][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:48.905 UTC [26483][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:48.913 UTC [26479][checkpointer] LOG:  shutting down
2024-03-10 07:49:48.917 UTC [26473][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638842111121172 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:49:49.100 UTC [26532][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-10 07:49:49.100 UTC [26532][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:49.104 UTC [26538][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:48 UTC
2024-03-10 07:49:49.105 UTC [26538][startup] LOG:  entering standby mode
2024-03-10 07:49:49.106 UTC [26538][startup] LOG:  redo starts at 0/3008C60
2024-03-10 07:49:49.106 UTC [26538][startup] LOG:  consistent recovery state reached at 0/3008C98
2024-03-10 07:49:49.106 UTC [26532][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:49.106 UTC [26538][startup] LOG:  invalid record length at 0/3008C98: expected at least 24, got 0
2024-03-10 07:49:49.157 UTC [26539][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: Done!
[07:49:49.456](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-10 07:49:49.496 UTC [26539][walreceiver] LOG:  replication terminated by primary server
2024-03-10 07:49:49.496 UTC [26539][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008D10.
2024-03-10 07:49:49.496 UTC [26539][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-10 07:49:49.500 UTC [26538][startup] LOG:  invalid record length at 0/3008D10: expected at least 24, got 0
2024-03-10 07:49:49.513 UTC [26597][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:49:49.513 UTC [26538][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 26613
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-10 07:49:49.853 UTC [26532][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:49.853 UTC [26532][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:49.857 UTC [26536][checkpointer] LOG:  shutting down
2024-03-10 07:49:49.857 UTC [26536][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-10 07:49:49.857 UTC [26536][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-10 07:49:49.857 UTC [26536][checkpointer] LOG:  recovery restart point at 0/3008C98
2024-03-10 07:49:49.861 UTC [26532][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-10 07:49:50.065 UTC [26687][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-10 07:49:50.065 UTC [26687][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:50.096 UTC [26691][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:49 UTC
2024-03-10 07:49:50.097 UTC [26691][startup] LOG:  entering standby mode
2024-03-10 07:49:50.099 UTC [26691][startup] LOG:  consistent recovery state reached at 0/3008D10
2024-03-10 07:49:50.099 UTC [26691][startup] LOG:  invalid record length at 0/3008D10: expected at least 24, got 0
2024-03-10 07:49:50.099 UTC [26687][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:50.123 UTC [26692][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:50.123 UTC [26691][startup] LOG:  redo starts at 0/3008D10
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:50.141 UTC [26700][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:50.142 UTC [26700][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-10 07:49:50.142 UTC [26700][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:50.169 UTC [26700][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:50.170 UTC [26700][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:50.170 UTC [26700][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-10 07:49:50.171 UTC [26700][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-10 07:49:50.187 UTC [26700][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.046 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.
[07:49:50.411](0.955s) 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-10 07:49:50.449 UTC [26692][walreceiver] LOG:  replication terminated by primary server
2024-03-10 07:49:50.449 UTC [26692][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008DC0.
2024-03-10 07:49:50.449 UTC [26692][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-10 07:49:50.450 UTC [26691][startup] LOG:  invalid record length at 0/3008DC0: expected at least 24, got 0
2024-03-10 07:49:50.457 UTC [26745][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:49:50.457 UTC [26691][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 26765
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-10 07:49:50.831 UTC [26687][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:50.831 UTC [26687][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:50.836 UTC [26689][checkpointer] LOG:  shutting down
2024-03-10 07:49:50.836 UTC [26689][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-10 07:49:50.836 UTC [26689][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-10 07:49:50.836 UTC [26689][checkpointer] LOG:  recovery restart point at 0/3008D48
2024-03-10 07:49:50.841 UTC [26687][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-10 07:49:51.056 UTC [26875][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-10 07:49:51.057 UTC [26875][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:51.095 UTC [26883][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:50 UTC
2024-03-10 07:49:51.095 UTC [26883][startup] LOG:  entering standby mode
2024-03-10 07:49:51.100 UTC [26883][startup] LOG:  consistent recovery state reached at 0/3008DC0
2024-03-10 07:49:51.100 UTC [26875][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:51.106 UTC [26883][startup] LOG:  invalid record length at 0/3008DC0: expected at least 24, got 0
2024-03-10 07:49:51.144 UTC [26886][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:51.144 UTC [26883][startup] LOG:  redo starts at 0/3008DC0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:51.185 UTC [26890][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:51.186 UTC [26890][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-10 07:49:51.186 UTC [26890][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:51.244 UTC [26890][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:51.263 UTC [26890][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:51.265 UTC [26890][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-10 07:49:51.277 UTC [26890][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-10 07:49:51.291 UTC [26890][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.106 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_26826" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_26826" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_26826" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_26826" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:49:51.517 UTC [26875][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:51.517 UTC [26875][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:51.517 UTC [26886][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:51.525 UTC [26879][checkpointer] LOG:  shutting down
2024-03-10 07:49:51.529 UTC [26875][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:49:51.777 UTC [26937][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-10 07:49:51.778 UTC [26937][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:51.816 UTC [26952][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:51 UTC
2024-03-10 07:49:51.816 UTC [26952][startup] LOG:  entering standby mode
2024-03-10 07:49:51.818 UTC [26952][startup] LOG:  redo starts at 0/3008DC0
2024-03-10 07:49:51.818 UTC [26952][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-10 07:49:51.818 UTC [26952][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-10 07:49:51.818 UTC [26937][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:51.835 UTC [26955][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-10 07:49:51.923 UTC [26963][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:51.924 UTC [26963][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-10 07:49:51.924 UTC [26963][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:51.967 UTC [26963][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:51.972 UTC [26963][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-10 07:49:51.973 UTC [26963][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.054 user=postgres database=pg1 host=[local]
2024-03-10 07:49:51.992 UTC [26969][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:51.993 UTC [26969][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-10 07:49:51.993 UTC [26969][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:51.997 UTC [26969][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_26826" on database "pg1"
2024-03-10 07:49:51.998 UTC [26969][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_26826'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_26826" on database "pg1"
2024-03-10 07:49:52.010 UTC [26969][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.018 user=postgres database=pg1 host=[local]
2024-03-10 07:49:52.022 UTC [26976][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:52.023 UTC [26976][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-10 07:49:52.023 UTC [26976][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:49:52.074 UTC [26976][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_26826" on database "pg2"
2024-03-10 07:49:52.075 UTC [26976][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_26826'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_26826" on database "pg2"
2024-03-10 07:49:52.077 UTC [26976][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.055 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-10 07:49:52.121 UTC [26937][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:52.121 UTC [26937][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:52.122 UTC [26955][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:52.132 UTC [26950][checkpointer] LOG:  shutting down
2024-03-10 07:49:52.135 UTC [26937][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638855870572746 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:49:52.405 UTC [27018][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-10 07:49:52.406 UTC [27018][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:52.420 UTC [27027][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:52 UTC
2024-03-10 07:49:52.420 UTC [27027][startup] LOG:  entering standby mode
2024-03-10 07:49:52.424 UTC [27027][startup] LOG:  redo starts at 0/3008DC0
2024-03-10 07:49:52.424 UTC [27027][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-10 07:49:52.424 UTC [27018][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:52.425 UTC [27027][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-10 07:49:52.484 UTC [27030][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
[07:49:52.783](2.372s) 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
waiting for server to shut down....2024-03-10 07:49:52.793 UTC [27018][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:52.793 UTC [27018][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:52.793 UTC [27030][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:52.800 UTC [27024][checkpointer] LOG:  shutting down
2024-03-10 07:49:52.804 UTC [27018][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 27093
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:49:53.411 UTC [27145][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-10 07:49:53.411 UTC [27145][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:53.436 UTC [27152][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:53 UTC
2024-03-10 07:49:53.436 UTC [27152][startup] LOG:  entering standby mode
2024-03-10 07:49:53.438 UTC [27152][startup] LOG:  redo starts at 0/3008DC0
2024-03-10 07:49:53.438 UTC [27152][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-10 07:49:53.438 UTC [27152][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-10 07:49:53.438 UTC [27145][postmaster] LOG:  database system is ready to accept read-only connections
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:53.465 UTC [27161][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:53.466 UTC [27161][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-10 07:49:53.466 UTC [27161][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:53.482 UTC [27157][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:53.500 UTC [27161][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:53.501 UTC [27161][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:53.503 UTC [27161][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-10 07:49:53.503 UTC [27161][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.
=================================================================
==27108==ERROR: AddressSanitizer: heap-use-after-free on address 0x61a000001458 at pc 0x7fe46082ddce bp 0x7ffcf74c2410 sp 0x7ffcf74c2408
READ of size 4 at 0x61a000001458 thread T0
    #0 0x7fe46082ddcd in sendTerminateConn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502
    #1 0x7fe46082f42e in pqClosePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4528
    #2 0x7fe46082f59c in PQfinish /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4566
    #3 0x557c14b3cde1 in disconnect_database /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:446
    #4 0x557c14b3e91d in check_subscriber /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:959
    #5 0x557c14b422bb in main /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:1983
    #6 0x7fe46062ed09 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x23d09)
    #7 0x557c14b3c859 in _start (/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_createsubscriber+0xd859)

0x61a000001458 is located 472 bytes inside of 1192-byte region [0x61a000001280,0x61a000001728)
freed by thread T0 here:
    #0 0x7fe46096ab6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123
    #1 0x7fe46082ef3b in freePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4406

previously allocated by thread T0 here:
    #0 0x7fe46096ae8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
    #1 0x7fe46082f080 in pqMakeEmptyPGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4263

SUMMARY: AddressSanitizer: heap-use-after-free /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502 in sendTerminateConn
Shadow bytes around the buggy address:
  0x0c347fff8230: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c347fff8240: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c347fff8250: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff8260: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff8270: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x0c347fff8280: fd fd fd fd fd fd fd fd fd fd fd[fd]fd fd fd fd
  0x0c347fff8290: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
  Shadow gap:              cc
==27108==ABORTING
2024-03-10 07:49:53.535 UTC [27161][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.071 user=postgres database=pg1 host=[local]
[07:49:53.651](0.868s) 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
waiting for server to shut down....2024-03-10 07:49:53.668 UTC [27145][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:53.668 UTC [27145][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:53.675 UTC [27157][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:53.679 UTC [27150][checkpointer] LOG:  shutting down
2024-03-10 07:49:53.683 UTC [27145][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 27184
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:49:54.306 UTC [27243][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-10 07:49:54.306 UTC [27243][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:54.332 UTC [27249][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:54 UTC
2024-03-10 07:49:54.333 UTC [27249][startup] LOG:  entering standby mode
2024-03-10 07:49:54.334 UTC [27249][startup] LOG:  redo starts at 0/3008DC0
2024-03-10 07:49:54.334 UTC [27249][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-10 07:49:54.334 UTC [27243][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:54.334 UTC [27249][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:49:54.366 UTC [27253][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:54.375 UTC [27257][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:54.376 UTC [27257][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-10 07:49:54.376 UTC [27257][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:54.407 UTC [27257][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:54.408 UTC [27257][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:54.408 UTC [27257][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-10 07:49:54.409 UTC [27257][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-10 07:49:54.416 UTC [27257][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.048 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_27201" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_27201" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_27201" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_27201" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:49:54.593 UTC [27243][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:54.593 UTC [27243][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:54.597 UTC [27253][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:54.607 UTC [27247][checkpointer] LOG:  shutting down
2024-03-10 07:49:54.612 UTC [27243][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:49:54.844 UTC [27320][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-10 07:49:54.844 UTC [27320][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:54.861 UTC [27324][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:54 UTC
2024-03-10 07:49:54.862 UTC [27324][startup] LOG:  entering standby mode
2024-03-10 07:49:54.863 UTC [27324][startup] LOG:  redo starts at 0/3008DC0
2024-03-10 07:49:54.863 UTC [27324][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-10 07:49:54.863 UTC [27324][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-10 07:49:54.863 UTC [27320][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-10 07:49:54.903 UTC [27325][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:54.911 UTC [27330][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:54.912 UTC [27330][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-10 07:49:54.912 UTC [27330][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:54.937 UTC [27330][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:54.938 UTC [27330][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-10 07:49:54.939 UTC [27330][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.035 user=postgres database=pg1 host=[local]
2024-03-10 07:49:54.947 UTC [27335][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:54.948 UTC [27335][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-10 07:49:54.948 UTC [27335][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:54.950 UTC [27335][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_27201" on database "pg1"
2024-03-10 07:49:54.950 UTC [27335][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_27201'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_27201" on database "pg1"
2024-03-10 07:49:54.956 UTC [27335][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.012 user=postgres database=pg1 host=[local]
2024-03-10 07:49:54.973 UTC [27337][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:54.973 UTC [27337][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-10 07:49:54.973 UTC [27337][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:49:54.988 UTC [27337][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_27201" on database "pg2"
2024-03-10 07:49:54.988 UTC [27337][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_27201'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_27201" on database "pg2"
2024-03-10 07:49:54.991 UTC [27337][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.023 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-10 07:49:55.004 UTC [27320][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:55.004 UTC [27320][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:55.004 UTC [27325][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:55.012 UTC [27322][checkpointer] LOG:  shutting down
2024-03-10 07:49:55.017 UTC [27320][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638868265806401 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:49:55.247 UTC [27367][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-10 07:49:55.247 UTC [27367][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:55.256 UTC [27378][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:55 UTC
2024-03-10 07:49:55.256 UTC [27378][startup] LOG:  entering standby mode
2024-03-10 07:49:55.258 UTC [27378][startup] LOG:  redo starts at 0/3008DC0
2024-03-10 07:49:55.258 UTC [27378][startup] LOG:  consistent recovery state reached at 0/3008DF8
2024-03-10 07:49:55.258 UTC [27378][startup] LOG:  invalid record length at 0/3008DF8: expected at least 24, got 0
2024-03-10 07:49:55.271 UTC [27367][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:55.291 UTC [27382][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: Done!
[07:49:55.623](1.973s) 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
waiting for server to shut down....2024-03-10 07:49:55.669 UTC [27382][walreceiver] LOG:  replication terminated by primary server
2024-03-10 07:49:55.669 UTC [27382][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008E70.
2024-03-10 07:49:55.669 UTC [27382][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-10 07:49:55.673 UTC [27378][startup] LOG:  invalid record length at 0/3008E70: expected at least 24, got 0
2024-03-10 07:49:55.700 UTC [27438][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:49:55.701 UTC [27378][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 27448
2024-03-10 07:49:56.220 UTC [27478][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-10 07:49:56.847 UTC [27367][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:56.847 UTC [27367][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:56.854 UTC [27478][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:56.867 UTC [27376][checkpointer] LOG:  shutting down
2024-03-10 07:49:56.867 UTC [27376][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-10 07:49:56.868 UTC [27376][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-10 07:49:56.868 UTC [27376][checkpointer] LOG:  recovery restart point at 0/3008DF8
2024-03-10 07:49:56.872 UTC [27367][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 27570
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:49:57.422 UTC [27672][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-10 07:49:57.422 UTC [27672][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:57.435 UTC [27686][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:57 UTC
2024-03-10 07:49:57.435 UTC [27686][startup] LOG:  entering standby mode
2024-03-10 07:49:57.437 UTC [27686][startup] LOG:  redo starts at 0/3008E70
2024-03-10 07:49:57.437 UTC [27686][startup] LOG:  consistent recovery state reached at 0/3008EA8
2024-03-10 07:49:57.437 UTC [27686][startup] LOG:  invalid record length at 0/3008EA8: expected at least 24, got 0
2024-03-10 07:49:57.437 UTC [27672][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:57.478 UTC [27689][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-10 07:49:57.507 UTC [27702][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:57.508 UTC [27702][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-10 07:49:57.508 UTC [27702][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:57.524 UTC [27702][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:57.525 UTC [27702][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:57.525 UTC [27702][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-10 07:49:57.526 UTC [27702][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.
=================================================================
==27605==ERROR: AddressSanitizer: heap-use-after-free on address 0x61a000001458 at pc 0x7fcf66a57dce bp 0x7fff785ccde0 sp 0x7fff785ccdd8
READ of size 4 at 0x61a000001458 thread T0
2024-03-10 07:49:57.542 UTC [27702][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.047 user=postgres database=pg1 host=[local]
    #0 0x7fcf66a57dcd in sendTerminateConn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502
    #1 0x7fcf66a5942e in pqClosePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4528
    #2 0x7fcf66a5959c in PQfinish /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4566
    #3 0x55c96077dde1 in disconnect_database /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:446
    #4 0x55c96077f971 in check_subscriber /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:968
    #5 0x55c9607832bb in main /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:1983
    #6 0x7fcf66858d09 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x23d09)
    #7 0x55c96077d859 in _start (/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_createsubscriber+0xd859)

0x61a000001458 is located 472 bytes inside of 1192-byte region [0x61a000001280,0x61a000001728)
freed by thread T0 here:
    #0 0x7fcf66b94b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123
    #1 0x7fcf66a58f3b in freePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4406

previously allocated by thread T0 here:
    #0 0x7fcf66b94e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145
    #1 0x7fcf66a59080 in pqMakeEmptyPGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4263

SUMMARY: AddressSanitizer: heap-use-after-free /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502 in sendTerminateConn
Shadow bytes around the buggy address:
  0x0c347fff8230: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c347fff8240: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c347fff8250: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff8260: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff8270: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
=>0x0c347fff8280: fd fd fd fd fd fd fd fd fd fd fd[fd]fd fd fd fd
  0x0c347fff8290: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82a0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82c0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c347fff82d0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07 
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
  Shadow gap:              cc
==27605==ABORTING
[07:49:57.700](2.077s) 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-10 07:49:57.749 UTC [27689][walreceiver] LOG:  replication terminated by primary server
2024-03-10 07:49:57.749 UTC [27689][walreceiver] DETAIL:  End of WAL reached on timeline 1 at 0/3008F20.
2024-03-10 07:49:57.749 UTC [27689][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-10 07:49:57.753 UTC [27686][startup] LOG:  invalid record length at 0/3008F20: expected at least 24, got 0
2024-03-10 07:49:57.766 UTC [27751][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:49:57.770 UTC [27686][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 27772
2024-03-10 07:49:58.284 UTC [27871][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:49:58.284 UTC [27686][startup] WARNING:  hot standby is not possible because of insufficient parameter settings
2024-03-10 07:49:58.284 UTC [27686][startup] DETAIL:  max_worker_processes = 2 is a lower setting than on the primary server, where its value was 3.
2024-03-10 07:49:58.284 UTC [27686][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-10 07:49:58.284 UTC [27686][startup] LOG:  recovery has paused
2024-03-10 07:49:58.284 UTC [27686][startup] DETAIL:  If recovery is unpaused, the server will shut down.
2024-03-10 07:49:58.284 UTC [27686][startup] HINT:  You can then restart the server after making the necessary configuration changes.
2024-03-10 07:49:58.284 UTC [27686][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
2024-03-10 07:49:58.928 UTC [27672][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:58.929 UTC [27672][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:58.930 UTC [27871][walreceiver] FATAL:  terminating walreceiver process due to administrator command
waiting for server to shut down....2024-03-10 07:49:59.289 UTC [27684][checkpointer] LOG:  shutting down
2024-03-10 07:49:59.289 UTC [27684][checkpointer] LOG:  restartpoint starting: shutdown immediate
2024-03-10 07:49:59.289 UTC [27684][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-10 07:49:59.289 UTC [27684][checkpointer] LOG:  recovery restart point at 0/3008EA8
2024-03-10 07:49:59.293 UTC [27672][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 28150
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:49:59.657 UTC [28228][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-10 07:49:59.657 UTC [28228][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:49:59.671 UTC [28237][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:59 UTC
2024-03-10 07:49:59.671 UTC [28237][startup] LOG:  entering standby mode
2024-03-10 07:49:59.673 UTC [28237][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:49:59.673 UTC [28237][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:49:59.673 UTC [28237][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-10 07:49:59.673 UTC [28228][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:49:59.690 UTC [28240][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-10 07:49:59.756 UTC [28249][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:49:59.757 UTC [28249][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-10 07:49:59.757 UTC [28249][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:49:59.787 UTC [28249][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:49:59.788 UTC [28249][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:49:59.788 UTC [28249][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-10 07:49:59.789 UTC [28249][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-10 07:49:59.793 UTC [28249][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.042 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_28178" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_28178" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_28178" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_28178" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:49:59.891 UTC [28228][postmaster] LOG:  received fast shutdown request
2024-03-10 07:49:59.891 UTC [28228][postmaster] LOG:  aborting any active transactions
2024-03-10 07:49:59.895 UTC [28240][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:49:59.899 UTC [28235][checkpointer] LOG:  shutting down
2024-03-10 07:49:59.904 UTC [28228][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:50:00.041 UTC [28309][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-10 07:50:00.041 UTC [28309][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:50:00.045 UTC [28321][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:49:59 UTC
2024-03-10 07:50:00.045 UTC [28321][startup] LOG:  entering standby mode
2024-03-10 07:50:00.047 UTC [28321][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:00.047 UTC [28321][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:00.047 UTC [28321][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-10 07:50:00.047 UTC [28309][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:00.052 UTC [28322][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-10 07:50:00.137 UTC [28345][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:00.138 UTC [28345][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-10 07:50:00.138 UTC [28345][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:00.159 UTC [28345][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:50:00.160 UTC [28345][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-10 07:50:00.162 UTC [28345][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.024 user=postgres database=pg1 host=[local]
2024-03-10 07:50:00.179 UTC [28354][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:00.180 UTC [28354][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-10 07:50:00.180 UTC [28354][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:00.182 UTC [28354][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_28178" on database "pg1"
2024-03-10 07:50:00.182 UTC [28354][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_28178'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_28178" on database "pg1"
2024-03-10 07:50:00.185 UTC [28354][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.005 user=postgres database=pg1 host=[local]
2024-03-10 07:50:00.193 UTC [28364][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:00.194 UTC [28364][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-10 07:50:00.194 UTC [28364][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:50:00.205 UTC [28364][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_28178" on database "pg2"
2024-03-10 07:50:00.205 UTC [28364][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_28178'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_28178" on database "pg2"
2024-03-10 07:50:00.208 UTC [28364][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.014 user=postgres database=pg2 host=[local]
pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1"
pg_createsubscriber: stopping the subscriber
2024-03-10 07:50:00.225 UTC [28309][postmaster] LOG:  received fast shutdown request
2024-03-10 07:50:00.225 UTC [28309][postmaster] LOG:  aborting any active transactions
2024-03-10 07:50:00.228 UTC [28322][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:50:00.235 UTC [28319][checkpointer] LOG:  shutting down
2024-03-10 07:50:00.239 UTC [28309][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638890681044498 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:50:00.377 UTC [28429][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-10 07:50:00.377 UTC [28429][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:50:00.396 UTC [28436][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:50:00 UTC
2024-03-10 07:50:00.396 UTC [28436][startup] LOG:  entering standby mode
2024-03-10 07:50:00.397 UTC [28436][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:00.397 UTC [28436][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:00.397 UTC [28429][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:00.397 UTC [28436][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-10 07:50:00.411 UTC [28442][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
pg_createsubscriber: server was started
pg_createsubscriber: Done!
[07:50:00.582](2.882s) 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/qWQuQEaj3q -p 65411 --checkpoint fast --no-sync
2024-03-10 07:50:00.601 UTC [28494][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:00.602 UTC [28494][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-10 07:50:00.602 UTC [28494][walsender] [[unknown]][17/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:00.609 UTC [28494][walsender] [041_tests.pl][17/0:0] LOG:  received replication command: SHOW data_directory_mode
2024-03-10 07:50:00.609 UTC [28494][walsender] [041_tests.pl][17/0:0] STATEMENT:  SHOW data_directory_mode
2024-03-10 07:50:00.609 UTC [28494][walsender] [041_tests.pl][17/0:0] LOG:  received replication command: SHOW wal_segment_size
2024-03-10 07:50:00.609 UTC [28494][walsender] [041_tests.pl][17/0:0] STATEMENT:  SHOW wal_segment_size
2024-03-10 07:50:00.609 UTC [28494][walsender] [041_tests.pl][17/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:00.609 UTC [28494][walsender] [041_tests.pl][17/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:00.609 UTC [28494][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-10 07:50:00.609 UTC [28494][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-10 07:50:00.634 UTC [28497][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:00.634 UTC [28497][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-10 07:50:00.634 UTC [28497][walsender] [[unknown]][18/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:00.636 UTC [28497][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: SHOW data_directory_mode
2024-03-10 07:50:00.636 UTC [28497][walsender] [041_tests.pl][18/0:0] STATEMENT:  SHOW data_directory_mode
2024-03-10 07:50:00.636 UTC [28497][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: CREATE_REPLICATION_SLOT "pg_basebackup_28497" TEMPORARY PHYSICAL ( RESERVE_WAL)
2024-03-10 07:50:00.636 UTC [28497][walsender] [041_tests.pl][18/0:0] STATEMENT:  CREATE_REPLICATION_SLOT "pg_basebackup_28497" TEMPORARY PHYSICAL ( RESERVE_WAL)
2024-03-10 07:50:00.636 UTC [28497][walsender] [041_tests.pl][18/0:0] LOG:  released physical replication slot "pg_basebackup_28497"
2024-03-10 07:50:00.636 UTC [28497][walsender] [041_tests.pl][18/0:0] STATEMENT:  CREATE_REPLICATION_SLOT "pg_basebackup_28497" TEMPORARY PHYSICAL ( RESERVE_WAL)
2024-03-10 07:50:00.654 UTC [28497][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:00.654 UTC [28497][walsender] [041_tests.pl][18/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:00.654 UTC [28497][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: START_REPLICATION SLOT "pg_basebackup_28497" 0/3000000 TIMELINE 1
2024-03-10 07:50:00.654 UTC [28497][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "pg_basebackup_28497" 0/3000000 TIMELINE 1
2024-03-10 07:50:00.654 UTC [28497][walsender] [041_tests.pl][18/0:0] LOG:  acquired physical replication slot "pg_basebackup_28497"
2024-03-10 07:50:00.654 UTC [28497][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "pg_basebackup_28497" 0/3000000 TIMELINE 1
2024-03-10 07:50:00.876 UTC [28497][walsender] [041_tests.pl][18/0:0] LOG:  released physical replication slot "pg_basebackup_28497"
2024-03-10 07:50:00.876 UTC [28497][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "pg_basebackup_28497" 0/3000000 TIMELINE 1
2024-03-10 07:50:00.878 UTC [28494][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.276 user=postgres database= host=[local]
2024-03-10 07:50:00.882 UTC [28497][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.250 user=postgres database= host=[local]
# Backup finished
# Checking port 65412
# Found port 65412
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=65412 host=/tmp/qWQuQEaj3q
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-10 07:50:01.298 UTC [28640][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:01.299 UTC [28640][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-10 07:50:01.299 UTC [28640][walsender] [[unknown]][19/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-10 07:50:01.299 UTC [28640][walsender] [node_c][19/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:01.299 UTC [28640][walsender] [node_c][19/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:01.300 UTC [28640][walsender] [node_c][19/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.300 UTC [28640][walsender] [node_c][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.300 UTC [28640][walsender] [node_c][19/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:01.300 UTC [28640][walsender] [node_c][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.305 UTC [28640][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.011 user=postgres database= host=[local]
 done
server started
# Postmaster PID for node "node_c" is 28626
# 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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65411 --database pg1 --database pg2
2024-03-10 07:50:01.335 UTC [28646][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:01.336 UTC [28646][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-10 07:50:01.336 UTC [28646][walsender] [[unknown]][20/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-10 07:50:01.343 UTC [28646][walsender] [node_c][20/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:01.343 UTC [28646][walsender] [node_c][20/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:01.343 UTC [28646][walsender] [node_c][20/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.343 UTC [28646][walsender] [node_c][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.343 UTC [28646][walsender] [node_c][20/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:01.343 UTC [28646][walsender] [node_c][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.343 UTC [28646][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.008 user=postgres database= host=[local]
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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 on subscriber
pg_createsubscriber: standby is up and running
pg_createsubscriber: stopping the server to start the transformation steps
2024-03-10 07:50:01.454 UTC [28429][postmaster] LOG:  received fast shutdown request
2024-03-10 07:50:01.454 UTC [28429][postmaster] LOG:  aborting any active transactions
2024-03-10 07:50:01.458 UTC [28442][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:50:01.467 UTC [28434][checkpointer] LOG:  shutting down
2024-03-10 07:50:01.471 UTC [28429][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: starting the standby with command-line options
2024-03-10 07:50:01.687 UTC [28701][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-10 07:50:01.687 UTC [28701][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:50:01.699 UTC [28709][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:50:01 UTC
2024-03-10 07:50:01.699 UTC [28709][startup] LOG:  entering standby mode
2024-03-10 07:50:01.700 UTC [28709][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:01.700 UTC [28709][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:01.700 UTC [28709][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-10 07:50:01.701 UTC [28701][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:01.732 UTC [28713][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-10 07:50:01.753 UTC [28721][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:01.753 UTC [28721][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-10 07:50:01.753 UTC [28721][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:01.776 UTC [28721][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:50:01.776 UTC [28721][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:50:01.777 UTC [28721][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-10 07:50:01.778 UTC [28721][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-10 07:50:01.782 UTC [28721][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.029 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_28649" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_28649" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_28649" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_28649" on publisher
2024-03-10 07:50:01.859 UTC [28740][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:01.860 UTC [28740][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-10 07:50:01.860 UTC [28740][walsender] [[unknown]][17/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-10 07:50:01.862 UTC [28740][walsender] [node_c][17/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:01.862 UTC [28740][walsender] [node_c][17/0:0] STATEMENT:  IDENTIFY_SYSTEM
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:50:01.863 UTC [28740][walsender] [node_c][17/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.863 UTC [28740][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.863 UTC [28740][walsender] [node_c][17/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:01.863 UTC [28740][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:01.865 UTC [28740][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.005 user=postgres database= host=[local]
2024-03-10 07:50:01.880 UTC [28701][postmaster] LOG:  received fast shutdown request
2024-03-10 07:50:01.881 UTC [28701][postmaster] LOG:  aborting any active transactions
2024-03-10 07:50:01.881 UTC [28713][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:50:01.885 UTC [28707][checkpointer] LOG:  shutting down
2024-03-10 07:50:01.890 UTC [28701][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:50:02.103 UTC [28784][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-10 07:50:02.103 UTC [28784][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:50:02.123 UTC [28798][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:50:01 UTC
2024-03-10 07:50:02.123 UTC [28798][startup] LOG:  entering standby mode
2024-03-10 07:50:02.143 UTC [28798][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:02.143 UTC [28798][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:02.143 UTC [28784][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:02.143 UTC [28798][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-10 07:50:02.173 UTC [28804][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:02.182 UTC [28804][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-10 07:50:02.182 UTC [28804][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:02.183 UTC [28802][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:50:02.218 UTC [28804][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:50:02.219 UTC [28804][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-10 07:50:02.221 UTC [28804][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.047 user=postgres database=pg1 host=[local]
2024-03-10 07:50:02.226 UTC [28816][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:02.227 UTC [28816][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-10 07:50:02.227 UTC [28816][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:02.233 UTC [28816][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_28649" on database "pg1"
2024-03-10 07:50:02.233 UTC [28816][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_28649'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_28649" on database "pg1"
2024-03-10 07:50:02.245 UTC [28816][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.019 user=postgres database=pg1 host=[local]
2024-03-10 07:50:02.247 UTC [28821][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:02.248 UTC [28821][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-10 07:50:02.248 UTC [28821][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:50:02.274 UTC [28821][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_28649" on database "pg2"
2024-03-10 07:50:02.277 UTC [28821][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_28649'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_28649" on database "pg2"
2024-03-10 07:50:02.279 UTC [28821][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-10 07:50:02.317 UTC [28784][postmaster] LOG:  received fast shutdown request
2024-03-10 07:50:02.317 UTC [28784][postmaster] LOG:  aborting any active transactions
2024-03-10 07:50:02.317 UTC [28802][walreceiver] FATAL:  terminating walreceiver process due to administrator command
2024-03-10 07:50:02.341 UTC [28796][checkpointer] LOG:  shutting down
2024-03-10 07:50:02.346 UTC [28784][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638899597541353 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:50:02.501 UTC [28871][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-10 07:50:02.501 UTC [28871][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65411"
2024-03-10 07:50:02.524 UTC [28881][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:50:02 UTC
2024-03-10 07:50:02.524 UTC [28881][startup] LOG:  entering standby mode
2024-03-10 07:50:02.526 UTC [28881][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:02.526 UTC [28881][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:02.526 UTC [28871][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:02.526 UTC [28881][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-10 07:50:02.562 UTC [28886][walreceiver] LOG:  started streaming WAL from primary at 0/3000000 on timeline 1
2024-03-10 07:50:02.834 UTC [28932][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:02.835 UTC [28932][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-10 07:50:02.835 UTC [28932][walsender] [[unknown]][17/1:0] LOG:  replication connection authorized: user=postgres application_name=node_c
2024-03-10 07:50:02.837 UTC [28932][walsender] [node_c][17/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:02.837 UTC [28932][walsender] [node_c][17/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:02.837 UTC [28932][walsender] [node_c][17/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:02.837 UTC [28932][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:02.837 UTC [28932][walsender] [node_c][17/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:02.837 UTC [28932][walsender] [node_c][17/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:02.841 UTC [28932][walsender] [node_c][:0] LOG:  disconnection: session time: 0:00:00.006 user=postgres database= host=[local]
[07:50:02.982](2.399s) not ok 13 - standby server is primary to other node
[07:50:02.982](0.000s) 
[07:50:02.982](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=65410 host=/tmp/qWQuQEaj3q dbname='pg1' --socket-directory /tmp/qWQuQEaj3q --subscriber-port 65412 --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 7344638515392293868 on publisher
pg_createsubscriber: getting system identifier from subscriber
pg_createsubscriber: system identifier is 7344638515392293868 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-10 07:50:03.235 UTC [29013][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-10 07:50:03.235 UTC [29013][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65412"
2024-03-10 07:50:03.239 UTC [29019][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:50:03 UTC
2024-03-10 07:50:03.239 UTC [29019][startup] LOG:  entering standby mode
2024-03-10 07:50:03.240 UTC [29019][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:03.240 UTC [29019][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:03.240 UTC [29013][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:03.240 UTC [29019][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-10 07:50:03.247 UTC [29022][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.248 UTC [29022][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-10 07:50:03.248 UTC [29022][walsender] [[unknown]][18/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:03.249 UTC [29022][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:03.249 UTC [29022][walsender] [041_tests.pl][18/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:03.249 UTC [29022][walsender] [041_tests.pl][18/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.249 UTC [29022][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.249 UTC [29022][walsender] [041_tests.pl][18/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.249 UTC [29022][walsender] [041_tests.pl][18/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.249 UTC [29020][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.253 UTC [29022][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.006 user=postgres database= host=[local]
2024-03-10 07:50:03.277 UTC [29033][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.278 UTC [29033][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-10 07:50:03.278 UTC [29033][walsender] [[unknown]][19/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:03.279 UTC [29033][walsender] [041_tests.pl][19/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:03.279 UTC [29033][walsender] [041_tests.pl][19/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:03.279 UTC [29033][walsender] [041_tests.pl][19/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.279 UTC [29033][walsender] [041_tests.pl][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.279 UTC [29033][walsender] [041_tests.pl][19/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.279 UTC [29033][walsender] [041_tests.pl][19/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.279 UTC [29027][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.281 UTC [29019][startup] LOG:  waiting for WAL to become available at 0/3002000
2024-03-10 07:50:03.283 UTC [29033][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.005 user=postgres database= host=[local]
pg_createsubscriber: server was started
pg_createsubscriber: checking settings on subscriber
2024-03-10 07:50:03.327 UTC [29042][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.328 UTC [29042][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-10 07:50:03.328 UTC [29042][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:03.341 UTC [29042][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:50:03.341 UTC [29042][client backend] [041_tests.pl][0/3:0] LOG:  statement: SELECT pg_catalog.pg_is_in_recovery()
2024-03-10 07:50:03.342 UTC [29042][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-10 07:50:03.343 UTC [29042][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-10 07:50:03.348 UTC [29042][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.020 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_28962" on database "pg1"
pg_createsubscriber: create replication slot "pg_createsubscriber_16384_28962" on publisher
pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2"
pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_28962" on database "pg2"
pg_createsubscriber: create replication slot "pg_createsubscriber_16385_28962" on publisher
pg_createsubscriber: stopping and starting the subscriber
2024-03-10 07:50:03.430 UTC [29013][postmaster] LOG:  received fast shutdown request
2024-03-10 07:50:03.430 UTC [29013][postmaster] LOG:  aborting any active transactions
2024-03-10 07:50:03.437 UTC [29017][checkpointer] LOG:  shutting down
2024-03-10 07:50:03.441 UTC [29013][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
2024-03-10 07:50:03.498 UTC [29080][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-10 07:50:03.498 UTC [29080][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65412"
2024-03-10 07:50:03.506 UTC [29086][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:50:03 UTC
2024-03-10 07:50:03.507 UTC [29086][startup] LOG:  entering standby mode
2024-03-10 07:50:03.508 UTC [29086][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:03.508 UTC [29086][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:03.508 UTC [29080][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:03.508 UTC [29086][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-10 07:50:03.535 UTC [29092][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.536 UTC [29092][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-10 07:50:03.536 UTC [29092][walsender] [[unknown]][20/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:03.539 UTC [29092][walsender] [041_tests.pl][20/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:03.539 UTC [29092][walsender] [041_tests.pl][20/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:03.540 UTC [29092][walsender] [041_tests.pl][20/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.540 UTC [29092][walsender] [041_tests.pl][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.540 UTC [29092][walsender] [041_tests.pl][20/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.540 UTC [29092][walsender] [041_tests.pl][20/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.540 UTC [29089][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.545 UTC [29092][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.012 user=postgres database= host=[local]
2024-03-10 07:50:03.583 UTC [29098][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
pg_createsubscriber: server was started
pg_createsubscriber: waiting for the target server to reach the consistent state
2024-03-10 07:50:03.584 UTC [29098][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-10 07:50:03.584 UTC [29098][walsender] [[unknown]][21/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:03.584 UTC [29098][walsender] [041_tests.pl][21/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:03.584 UTC [29098][walsender] [041_tests.pl][21/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:03.585 UTC [29098][walsender] [041_tests.pl][21/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.585 UTC [29098][walsender] [041_tests.pl][21/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.585 UTC [29098][walsender] [041_tests.pl][21/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.585 UTC [29098][walsender] [041_tests.pl][21/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.585 UTC [29096][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.589 UTC [29086][startup] LOG:  waiting for WAL to become available at 0/3002000
2024-03-10 07:50:03.589 UTC [29098][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.009 user=postgres database= host=[local]
2024-03-10 07:50:03.599 UTC [29105][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.600 UTC [29105][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-10 07:50:03.600 UTC [29105][client backend] [[unknown]][0/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:03.622 UTC [29105][client backend] [041_tests.pl][0/2:0] LOG:  statement: SELECT pg_catalog.set_config('search_path', '', false);
2024-03-10 07:50:03.624 UTC [29105][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-10 07:50:03.625 UTC [29105][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.028 user=postgres database=pg1 host=[local]
2024-03-10 07:50:03.639 UTC [29117][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.640 UTC [29117][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-10 07:50:03.640 UTC [29117][client backend] [[unknown]][1/1:0] LOG:  connection authorized: user=postgres database=pg1 application_name=041_tests.pl
2024-03-10 07:50:03.642 UTC [29117][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_28962" on database "pg1"
2024-03-10 07:50:03.651 UTC [29117][client backend] [041_tests.pl][1/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_28962'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_28962" on database "pg1"
2024-03-10 07:50:03.654 UTC [29117][client backend] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.016 user=postgres database=pg1 host=[local]
2024-03-10 07:50:03.661 UTC [29126][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.662 UTC [29126][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-10 07:50:03.662 UTC [29126][client backend] [[unknown]][2/1:0] LOG:  connection authorized: user=postgres database=pg2 application_name=041_tests.pl
2024-03-10 07:50:03.686 UTC [29126][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_28962" on database "pg2"
2024-03-10 07:50:03.687 UTC [29126][client backend] [041_tests.pl][2/3:0] LOG:  statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_28962'
pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2"
pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_28962" on database "pg2"
2024-03-10 07:50:03.690 UTC [29126][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-10 07:50:03.708 UTC [29080][postmaster] LOG:  received fast shutdown request
2024-03-10 07:50:03.708 UTC [29080][postmaster] LOG:  aborting any active transactions
2024-03-10 07:50:03.713 UTC [29083][checkpointer] LOG:  shutting down
2024-03-10 07:50:03.717 UTC [29080][postmaster] LOG:  database system is shut down
pg_createsubscriber: server was stopped
pg_createsubscriber: modifying system identifier from subscriber
pg_createsubscriber: system identifier is 7344638905496416546 on subscriber
pg_createsubscriber: running pg_resetwal on the subscriber
2024-03-10 07:50:03.943 UTC [29194][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-10 07:50:03.943 UTC [29194][postmaster] LOG:  listening on Unix socket "/tmp/qWQuQEaj3q/.s.PGSQL.65412"
2024-03-10 07:50:03.967 UTC [29207][startup] LOG:  database system was shut down in recovery at 2024-03-10 07:50:03 UTC
2024-03-10 07:50:03.967 UTC [29207][startup] LOG:  entering standby mode
2024-03-10 07:50:03.969 UTC [29207][startup] LOG:  redo starts at 0/3008F20
2024-03-10 07:50:03.969 UTC [29207][startup] LOG:  consistent recovery state reached at 0/3008F58
2024-03-10 07:50:03.969 UTC [29207][startup] LOG:  invalid record length at 0/3008F58: expected at least 24, got 0
2024-03-10 07:50:03.969 UTC [29194][postmaster] LOG:  database system is ready to accept read-only connections
2024-03-10 07:50:03.985 UTC [29214][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:03.985 UTC [29214][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-10 07:50:03.985 UTC [29214][walsender] [[unknown]][22/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:03.986 UTC [29214][walsender] [041_tests.pl][22/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:03.986 UTC [29214][walsender] [041_tests.pl][22/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:03.986 UTC [29214][walsender] [041_tests.pl][22/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.986 UTC [29214][walsender] [041_tests.pl][22/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.986 UTC [29214][walsender] [041_tests.pl][22/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.986 UTC [29214][walsender] [041_tests.pl][22/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:03.986 UTC [29212][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:03.990 UTC [29214][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.005 user=postgres database= host=[local]
2024-03-10 07:50:03.999 UTC [29224][not initialized] [[unknown]][:0] LOG:  connection received: host=[local]
2024-03-10 07:50:04.000 UTC [29224][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-10 07:50:04.000 UTC [29224][walsender] [[unknown]][23/1:0] LOG:  replication connection authorized: user=postgres application_name=041_tests.pl
2024-03-10 07:50:04.000 UTC [29224][walsender] [041_tests.pl][23/0:0] LOG:  received replication command: IDENTIFY_SYSTEM
2024-03-10 07:50:04.000 UTC [29224][walsender] [041_tests.pl][23/0:0] STATEMENT:  IDENTIFY_SYSTEM
2024-03-10 07:50:04.000 UTC [29224][walsender] [041_tests.pl][23/0:0] LOG:  received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:04.000 UTC [29224][walsender] [041_tests.pl][23/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:04.000 UTC [29224][walsender] [041_tests.pl][23/0:0] ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:04.000 UTC [29224][walsender] [041_tests.pl][23/0:0] STATEMENT:  START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1
2024-03-10 07:50:04.000 UTC [29219][walreceiver] FATAL:  could not start WAL streaming: ERROR:  replication slot "physical_slot" does not exist
2024-03-10 07:50:04.001 UTC [29207][startup] LOG:  waiting for WAL to become available at 0/3002000
pg_createsubscriber: server was started
pg_createsubscriber: Done!
2024-03-10 07:50:04.018 UTC [29224][walsender] [041_tests.pl][:0] LOG:  disconnection: session time: 0:00:00.018 user=postgres database= host=[local]
[07:50:04.125](1.143s) not ok 14 - standby server is not direct standby of publisher
[07:50:04.126](0.000s) 
[07:50:04.126](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-10 07:50:04.143 UTC [28886][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-10 07:50:04.156 UTC [29267][walreceiver] FATAL:  could not connect to the primary server: connection to server on socket "/tmp/qWQuQEaj3q/.s.PGSQL.65410" failed: No such file or directory
		Is the server running locally and accepting connections on that socket?
2024-03-10 07:50:04.156 UTC [28881][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
waiting for server to shut down....2024-03-10 07:50:04.245 UTC [28871][postmaster] LOG:  received immediate shutdown request
2024-03-10 07:50:04.250 UTC [28871][postmaster] LOG:  database system is 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
waiting for server to shut down....2024-03-10 07:50:04.355 UTC [29194][postmaster] LOG:  received immediate shutdown request
2024-03-10 07:50:04.357 UTC [29194][postmaster] LOG:  database system is shut down
 done
server stopped
# No postmaster PID for node "node_c"
[07:50:04.457](0.331s) 1..14
[07:50:04.458](0.001s) # Looks like you failed 2 tests of 14.