# Checking port 60895 # Found port 60895 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=60895 host=/tmp/UpBJYi7JVt Log file: /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_p.log [14:26:58.181](0.048s) # 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 28038 # 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/UpBJYi7JVt -p 60895 --checkpoint fast --no-sync # Backup finished # Checking port 60896 # Found port 60896 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=60896 host=/tmp/UpBJYi7JVt 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 28231 ### 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 28250 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:00.535 UTC [28322][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-07 14:27:00.536 UTC [28322][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:00.554 UTC [28330][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:00 UTC 2024-03-07 14:27:00.554 UTC [28330][startup] LOG: entering standby mode 2024-03-07 14:27:00.555 UTC [28330][startup] LOG: consistent recovery state reached at 0/30000A0 2024-03-07 14:27:00.555 UTC [28330][startup] LOG: invalid record length at 0/30000A0: expected at least 24, got 0 2024-03-07 14:27:00.555 UTC [28322][postmaster] LOG: database system is ready to accept read-only connections pg_createsubscriber: server was started pg_createsubscriber: checking settings on subscriber 2024-03-07 14:27:00.590 UTC [28332][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:00.590 UTC [28330][startup] LOG: redo starts at 0/30000A0 2024-03-07 14:27:00.591 UTC [28338][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:00.593 UTC [28338][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-07 14:27:00.593 UTC [28338][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:00.629 UTC [28338][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:00.630 UTC [28338][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:00.636 UTC [28338][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-07 14:27:00.638 UTC [28338][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-07 14:27:00.674 UTC [28338][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.082 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. [14:27:00.784](2.603s) 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-07 14:27:00.840 UTC [28332][walreceiver] LOG: replication terminated by primary server 2024-03-07 14:27:00.840 UTC [28332][walreceiver] DETAIL: End of WAL reached on timeline 1 at 0/3004628. 2024-03-07 14:27:00.840 UTC [28332][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-07 14:27:00.845 UTC [28330][startup] LOG: invalid record length at 0/3004628: expected at least 24, got 0 2024-03-07 14:27:00.887 UTC [28395][walreceiver] FATAL: could not connect to the primary server: connection to server on socket "/tmp/UpBJYi7JVt/.s.PGSQL.60895" failed: No such file or directory Is the server running locally and accepting connections on that socket? 2024-03-07 14:27:00.887 UTC [28330][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 28398 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 2024-03-07 14:27:01.385 UTC [28427][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 pg_createsubscriber: system identifier is 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 on subscriber pg_createsubscriber: standby is up and running pg_createsubscriber: stopping the server to start the transformation steps 2024-03-07 14:27:01.450 UTC [28322][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:01.451 UTC [28322][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:01.451 UTC [28427][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:01.460 UTC [28327][checkpointer] LOG: shutting down 2024-03-07 14:27:01.460 UTC [28327][checkpointer] LOG: restartpoint starting: shutdown immediate 2024-03-07 14:27:01.460 UTC [28327][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-07 14:27:01.460 UTC [28327][checkpointer] LOG: recovery restart point at 0/30045B0 2024-03-07 14:27:01.465 UTC [28322][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: starting the standby with command-line options 2024-03-07 14:27:01.752 UTC [28450][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-07 14:27:01.752 UTC [28450][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:01.788 UTC [28461][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:01 UTC 2024-03-07 14:27:01.788 UTC [28461][startup] LOG: entering standby mode 2024-03-07 14:27:01.790 UTC [28461][startup] LOG: consistent recovery state reached at 0/3004628 2024-03-07 14:27:01.790 UTC [28461][startup] LOG: invalid record length at 0/3004628: expected at least 24, got 0 2024-03-07 14:27:01.790 UTC [28450][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:01.844 UTC [28466][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-07 14:27:01.883 UTC [28472][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:01.884 UTC [28472][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-07 14:27:01.884 UTC [28472][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:01.925 UTC [28472][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:01.927 UTC [28472][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:01.928 UTC [28472][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-07 14:27:01.930 UTC [28472][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-07 14:27:01.942 UTC [28472][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.063 user=postgres database=pg1 host=[local] pg_createsubscriber: primary has replication slot "physical_slot" pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_28418" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_28418" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_28418" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_28418" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:02.156 UTC [28461][startup] LOG: redo starts at 0/3004628 2024-03-07 14:27:02.171 UTC [28450][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:02.171 UTC [28450][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:02.180 UTC [28466][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:02.189 UTC [28459][checkpointer] LOG: shutting down 2024-03-07 14:27:02.194 UTC [28450][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:02.458 UTC [28509][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-07 14:27:02.458 UTC [28509][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:02.476 UTC [28520][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:02 UTC 2024-03-07 14:27:02.476 UTC [28520][startup] LOG: entering standby mode 2024-03-07 14:27:02.478 UTC [28520][startup] LOG: redo starts at 0/3004628 2024-03-07 14:27:02.478 UTC [28520][startup] LOG: invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3008000, offset 32768 2024-03-07 14:27:02.478 UTC [28520][startup] LOG: consistent recovery state reached at 0/3006BD0 2024-03-07 14:27:02.478 UTC [28520][startup] LOG: invalid magic number 0000 in WAL segment 000000010000000000000003, LSN 0/3008000, offset 32768 2024-03-07 14:27:02.478 UTC [28509][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-07 14:27:02.498 UTC [28525][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:02.499 UTC [28525][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-07 14:27:02.499 UTC [28525][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:02.527 UTC [28523][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:02.547 UTC [28525][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:02.549 UTC [28525][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-07 14:27:02.554 UTC [28525][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.056 user=postgres database=pg1 host=[local] 2024-03-07 14:27:02.568 UTC [28533][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:02.569 UTC [28533][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-07 14:27:02.569 UTC [28533][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:02.574 UTC [28533][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_28418" on database "pg1" 2024-03-07 14:27:02.576 UTC [28533][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_28418' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_28418" on database "pg1" 2024-03-07 14:27:02.582 UTC [28533][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.016 user=postgres database=pg1 host=[local] 2024-03-07 14:27:02.598 UTC [28538][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:02.599 UTC [28538][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-07 14:27:02.599 UTC [28538][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:02.650 UTC [28538][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_28418" on database "pg2" 2024-03-07 14:27:02.653 UTC [28538][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_28418' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_28418" on database "pg2" 2024-03-07 14:27:02.661 UTC [28538][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.065 user=postgres database=pg2 host=[local] pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1" pg_createsubscriber: stopping the subscriber 2024-03-07 14:27:02.695 UTC [28509][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:02.695 UTC [28509][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:02.696 UTC [28523][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:02.705 UTC [28518][checkpointer] LOG: shutting down 2024-03-07 14:27:02.710 UTC [28509][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343627951430323970 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:02.885 UTC [28565][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-07 14:27:02.886 UTC [28565][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:02.901 UTC [28580][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:02 UTC 2024-03-07 14:27:02.901 UTC [28580][startup] LOG: entering standby mode 2024-03-07 14:27:02.903 UTC [28580][startup] LOG: redo starts at 0/3004628 2024-03-07 14:27:02.903 UTC [28580][startup] LOG: consistent recovery state reached at 0/3008B38 2024-03-07 14:27:02.903 UTC [28580][startup] LOG: invalid record length at 0/3008B38: expected at least 24, got 0 2024-03-07 14:27:02.903 UTC [28565][postmaster] LOG: database system is ready to accept read-only connections pg_createsubscriber: server was started pg_createsubscriber: Done! 2024-03-07 14:27:02.958 UTC [28581][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 [14:27:03.363](2.579s) 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-07 14:27:03.371 UTC [28565][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:03.371 UTC [28565][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:03.380 UTC [28581][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:03.388 UTC [28577][checkpointer] LOG: shutting down 2024-03-07 14:27:03.392 UTC [28565][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 28641 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:03.858 UTC [28705][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-07 14:27:03.858 UTC [28705][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:03.877 UTC [28712][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:03 UTC 2024-03-07 14:27:03.878 UTC [28712][startup] LOG: entering standby mode 2024-03-07 14:27:03.881 UTC [28712][startup] LOG: redo starts at 0/3004628 2024-03-07 14:27:03.881 UTC [28712][startup] LOG: consistent recovery state reached at 0/3008B38 2024-03-07 14:27:03.882 UTC [28705][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:03.882 UTC [28712][startup] LOG: invalid record length at 0/3008B38: expected at least 24, got 0 2024-03-07 14:27:03.914 UTC [28716][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-07 14:27:03.941 UTC [28721][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:03.947 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-07 14:27:03.951 UTC [28721][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:03.990 UTC [28721][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:03.991 UTC [28721][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:03.992 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-07 14:27:03.993 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: error: subscriber requires 2 replication slots, but only 1 remain pg_createsubscriber: hint: Consider increasing max_replication_slots to at least 2. ================================================================= ==28648==ERROR: AddressSanitizer: heap-use-after-free on address 0x61a000001458 at pc 0x7f343e1ebdce bp 0x7fffc2df1970 sp 0x7fffc2df1968 READ of size 4 at 0x61a000001458 thread T0 2024-03-07 14:27:04.005 UTC [28721][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.066 user=postgres database=pg1 host=[local] #0 0x7f343e1ebdcd in sendTerminateConn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502 #1 0x7f343e1ed42e in pqClosePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4528 #2 0x7f343e1ed59c in PQfinish /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4566 #3 0x55f7ab962df1 in disconnect_database /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:446 #4 0x55f7ab9648dc in check_subscriber /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:950 #5 0x55f7ab9682cb in main /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:1977 #6 0x7f343dfecd09 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x23d09) #7 0x55f7ab962869 in _start (/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_createsubscriber+0xd869) 0x61a000001458 is located 472 bytes inside of 1192-byte region [0x61a000001280,0x61a000001728) freed by thread T0 here: #0 0x7f343e328b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123 #1 0x7f343e1ecf3b in freePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4406 previously allocated by thread T0 here: #0 0x7f343e328e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145 #1 0x7f343e1ed080 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 ==28648==ABORTING [14:27:04.220](0.857s) ok 3 - max_replication_slots are less in number in subscriber ### Restarting node "node_s" # Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart waiting for server to shut down....2024-03-07 14:27:04.248 UTC [28705][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:04.248 UTC [28705][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:04.248 UTC [28716][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:04.257 UTC [28710][checkpointer] LOG: shutting down 2024-03-07 14:27:04.262 UTC [28705][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 28796 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:04.817 UTC [28883][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-07 14:27:04.817 UTC [28883][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:04.823 UTC [28893][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:04 UTC 2024-03-07 14:27:04.823 UTC [28893][startup] LOG: entering standby mode 2024-03-07 14:27:04.825 UTC [28893][startup] LOG: redo starts at 0/3004628 2024-03-07 14:27:04.825 UTC [28893][startup] LOG: consistent recovery state reached at 0/3008B38 2024-03-07 14:27:04.825 UTC [28883][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:04.825 UTC [28893][startup] LOG: invalid record length at 0/3008B38: expected at least 24, got 0 2024-03-07 14:27:04.840 UTC [28895][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-07 14:27:04.876 UTC [28908][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:04.877 UTC [28908][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-07 14:27:04.877 UTC [28908][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:04.932 UTC [28908][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:04.933 UTC [28908][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:04.933 UTC [28908][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-07 14:27:04.935 UTC [28908][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-07 14:27:04.955 UTC [28908][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.082 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_28821" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_28821" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_28821" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_28821" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:05.061 UTC [28883][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:05.061 UTC [28883][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:05.068 UTC [28895][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:05.075 UTC [28890][checkpointer] LOG: shutting down 2024-03-07 14:27:05.080 UTC [28883][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:05.315 UTC [28985][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-07 14:27:05.315 UTC [28985][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:05.343 UTC [29000][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:05 UTC 2024-03-07 14:27:05.343 UTC [29000][startup] LOG: entering standby mode 2024-03-07 14:27:05.345 UTC [29000][startup] LOG: redo starts at 0/3004628 2024-03-07 14:27:05.345 UTC [29000][startup] LOG: consistent recovery state reached at 0/3008B38 2024-03-07 14:27:05.345 UTC [29000][startup] LOG: invalid record length at 0/3008B38: expected at least 24, got 0 2024-03-07 14:27:05.347 UTC [28985][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-07 14:27:05.374 UTC [29011][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:05.375 UTC [29015][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:05.376 UTC [29015][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-07 14:27:05.376 UTC [29015][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:05.420 UTC [29015][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:05.422 UTC [29015][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-07 14:27:05.425 UTC [29015][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.050 user=postgres database=pg1 host=[local] 2024-03-07 14:27:05.434 UTC [29021][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:05.435 UTC [29021][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-07 14:27:05.435 UTC [29021][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:05.437 UTC [29021][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_28821" on database "pg1" 2024-03-07 14:27:05.443 UTC [29021][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_28821' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_28821" on database "pg1" 2024-03-07 14:27:05.446 UTC [29021][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.013 user=postgres database=pg1 host=[local] 2024-03-07 14:27:05.456 UTC [29024][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:05.457 UTC [29024][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-07 14:27:05.457 UTC [29024][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:05.488 UTC [29024][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_28821" on database "pg2" 2024-03-07 14:27:05.490 UTC [29024][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_28821' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_28821" on database "pg2" 2024-03-07 14:27:05.499 UTC [29024][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.047 user=postgres database=pg2 host=[local] pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1" pg_createsubscriber: stopping the subscriber 2024-03-07 14:27:05.533 UTC [28985][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:05.533 UTC [28985][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:05.534 UTC [29011][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:05.546 UTC [28996][checkpointer] LOG: shutting down 2024-03-07 14:27:05.552 UTC [28985][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343627964040667285 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:05.796 UTC [29060][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-07 14:27:05.796 UTC [29060][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:05.806 UTC [29066][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:05 UTC 2024-03-07 14:27:05.807 UTC [29066][startup] LOG: entering standby mode 2024-03-07 14:27:05.808 UTC [29066][startup] LOG: redo starts at 0/3004628 2024-03-07 14:27:05.808 UTC [29066][startup] LOG: consistent recovery state reached at 0/3008B38 2024-03-07 14:27:05.808 UTC [29066][startup] LOG: invalid record length at 0/3008B38: expected at least 24, got 0 2024-03-07 14:27:05.809 UTC [29060][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:05.838 UTC [29068][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 pg_createsubscriber: server was started pg_createsubscriber: Done! [14:27:06.095](1.875s) 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-07 14:27:06.138 UTC [29068][walreceiver] LOG: replication terminated by primary server 2024-03-07 14:27:06.138 UTC [29068][walreceiver] DETAIL: End of WAL reached on timeline 1 at 0/3008BB0. 2024-03-07 14:27:06.138 UTC [29068][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-07 14:27:06.142 UTC [29066][startup] LOG: invalid record length at 0/3008BB0: expected at least 24, got 0 2024-03-07 14:27:06.145 UTC [29135][walreceiver] FATAL: could not connect to the primary server: connection to server on socket "/tmp/UpBJYi7JVt/.s.PGSQL.60895" failed: No such file or directory Is the server running locally and accepting connections on that socket? 2024-03-07 14:27:06.146 UTC [29066][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 29151 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 on subscriber pg_createsubscriber: standby is up and running pg_createsubscriber: stopping the server to start the transformation steps 2024-03-07 14:27:06.485 UTC [29060][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:06.485 UTC [29060][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:06.490 UTC [29064][checkpointer] LOG: shutting down 2024-03-07 14:27:06.490 UTC [29064][checkpointer] LOG: restartpoint starting: shutdown immediate 2024-03-07 14:27:06.491 UTC [29064][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-07 14:27:06.491 UTC [29064][checkpointer] LOG: recovery restart point at 0/3008B38 2024-03-07 14:27:06.496 UTC [29060][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: starting the standby with command-line options 2024-03-07 14:27:06.632 UTC [29231][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-07 14:27:06.632 UTC [29231][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:06.663 UTC [29243][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:06 UTC 2024-03-07 14:27:06.666 UTC [29243][startup] LOG: entering standby mode 2024-03-07 14:27:06.667 UTC [29243][startup] LOG: consistent recovery state reached at 0/3008BB0 2024-03-07 14:27:06.667 UTC [29243][startup] LOG: invalid record length at 0/3008BB0: expected at least 24, got 0 2024-03-07 14:27:06.667 UTC [29231][postmaster] LOG: database system is ready to accept read-only connections pg_createsubscriber: server was started pg_createsubscriber: checking settings on subscriber 2024-03-07 14:27:06.697 UTC [29256][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:06.698 UTC [29256][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-07 14:27:06.698 UTC [29256][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:06.705 UTC [29252][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:06.706 UTC [29243][startup] LOG: redo starts at 0/3008BB0 2024-03-07 14:27:06.749 UTC [29256][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:06.752 UTC [29256][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:06.753 UTC [29256][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-07 14:27:06.756 UTC [29256][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-07 14:27:06.769 UTC [29256][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.073 user=postgres database=pg1 host=[local] pg_createsubscriber: primary has replication slot "physical_slot" pg_createsubscriber: error: publisher requires wal_level >= logical [14:27:06.962](0.867s) 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-07 14:27:07.007 UTC [29252][walreceiver] LOG: replication terminated by primary server 2024-03-07 14:27:07.007 UTC [29252][walreceiver] DETAIL: End of WAL reached on timeline 1 at 0/3008C60. 2024-03-07 14:27:07.007 UTC [29252][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-07 14:27:07.008 UTC [29243][startup] LOG: invalid record length at 0/3008C60: expected at least 24, got 0 2024-03-07 14:27:07.035 UTC [29298][walreceiver] FATAL: could not connect to the primary server: connection to server on socket "/tmp/UpBJYi7JVt/.s.PGSQL.60895" failed: No such file or directory Is the server running locally and accepting connections on that socket? 2024-03-07 14:27:07.035 UTC [29243][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 29311 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 on subscriber pg_createsubscriber: standby is up and running pg_createsubscriber: stopping the server to start the transformation steps 2024-03-07 14:27:07.296 UTC [29231][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:07.296 UTC [29231][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:07.301 UTC [29240][checkpointer] LOG: shutting down 2024-03-07 14:27:07.301 UTC [29240][checkpointer] LOG: restartpoint starting: shutdown immediate 2024-03-07 14:27:07.301 UTC [29240][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-07 14:27:07.301 UTC [29240][checkpointer] LOG: recovery restart point at 0/3008BE8 2024-03-07 14:27:07.306 UTC [29231][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: starting the standby with command-line options 2024-03-07 14:27:07.707 UTC [29462][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-07 14:27:07.707 UTC [29462][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:07.745 UTC [29490][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:07 UTC 2024-03-07 14:27:07.745 UTC [29490][startup] LOG: entering standby mode 2024-03-07 14:27:07.746 UTC [29490][startup] LOG: consistent recovery state reached at 0/3008C60 2024-03-07 14:27:07.746 UTC [29490][startup] LOG: invalid record length at 0/3008C60: expected at least 24, got 0 2024-03-07 14:27:07.746 UTC [29462][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:07.795 UTC [29495][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:07.795 UTC [29490][startup] LOG: redo starts at 0/3008C60 pg_createsubscriber: server was started pg_createsubscriber: checking settings on subscriber 2024-03-07 14:27:07.857 UTC [29504][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:07.857 UTC [29504][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-07 14:27:07.857 UTC [29504][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:07.967 UTC [29504][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:07.968 UTC [29504][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:07.968 UTC [29504][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-07 14:27:07.969 UTC [29504][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-07 14:27:07.996 UTC [29504][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.144 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_29341" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_29341" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_29341" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_29341" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:08.419 UTC [29462][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:08.419 UTC [29462][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:08.428 UTC [29495][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:08.432 UTC [29488][checkpointer] LOG: shutting down 2024-03-07 14:27:08.438 UTC [29462][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:08.817 UTC [29581][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-07 14:27:08.817 UTC [29581][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:08.848 UTC [29598][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:08 UTC 2024-03-07 14:27:08.848 UTC [29598][startup] LOG: entering standby mode 2024-03-07 14:27:08.856 UTC [29598][startup] LOG: redo starts at 0/3008C60 2024-03-07 14:27:08.856 UTC [29598][startup] LOG: consistent recovery state reached at 0/3008C98 2024-03-07 14:27:08.856 UTC [29581][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:08.856 UTC [29598][startup] LOG: invalid record length at 0/3008C98: expected at least 24, got 0 2024-03-07 14:27:08.901 UTC [29606][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-07 14:27:08.926 UTC [29617][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:08.927 UTC [29617][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-07 14:27:08.927 UTC [29617][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:08.999 UTC [29617][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:09.002 UTC [29617][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-07 14:27:09.006 UTC [29617][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.082 user=postgres database=pg1 host=[local] 2024-03-07 14:27:09.008 UTC [29633][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:09.009 UTC [29633][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-07 14:27:09.009 UTC [29633][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:09.016 UTC [29633][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_29341" on database "pg1" 2024-03-07 14:27:09.017 UTC [29633][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_29341' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_29341" on database "pg1" 2024-03-07 14:27:09.018 UTC [29633][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.011 user=postgres database=pg1 host=[local] 2024-03-07 14:27:09.041 UTC [29635][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:09.042 UTC [29635][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-07 14:27:09.042 UTC [29635][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:09.108 UTC [29635][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_29341" on database "pg2" 2024-03-07 14:27:09.111 UTC [29635][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_29341' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_29341" on database "pg2" 2024-03-07 14:27:09.124 UTC [29635][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.083 user=postgres database=pg2 host=[local] pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1" pg_createsubscriber: stopping the subscriber 2024-03-07 14:27:09.170 UTC [29581][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:09.170 UTC [29581][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:09.175 UTC [29606][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:09.179 UTC [29595][checkpointer] LOG: shutting down 2024-03-07 14:27:09.185 UTC [29581][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343627979701559965 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:09.478 UTC [29689][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-07 14:27:09.478 UTC [29689][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:09.519 UTC [29703][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:09 UTC 2024-03-07 14:27:09.520 UTC [29703][startup] LOG: entering standby mode 2024-03-07 14:27:09.522 UTC [29703][startup] LOG: redo starts at 0/3008C60 2024-03-07 14:27:09.522 UTC [29703][startup] LOG: consistent recovery state reached at 0/3008C98 2024-03-07 14:27:09.522 UTC [29703][startup] LOG: invalid record length at 0/3008C98: expected at least 24, got 0 2024-03-07 14:27:09.522 UTC [29689][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:09.566 UTC [29708][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 pg_createsubscriber: server was started pg_createsubscriber: Done! [14:27:09.824](2.862s) 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-07 14:27:09.860 UTC [29708][walreceiver] LOG: replication terminated by primary server 2024-03-07 14:27:09.860 UTC [29708][walreceiver] DETAIL: End of WAL reached on timeline 1 at 0/3008D10. 2024-03-07 14:27:09.860 UTC [29708][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-07 14:27:09.864 UTC [29703][startup] LOG: invalid record length at 0/3008D10: expected at least 24, got 0 2024-03-07 14:27:09.872 UTC [29742][walreceiver] FATAL: could not connect to the primary server: connection to server on socket "/tmp/UpBJYi7JVt/.s.PGSQL.60895" failed: No such file or directory Is the server running locally and accepting connections on that socket? 2024-03-07 14:27:09.872 UTC [29703][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 29750 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 on subscriber pg_createsubscriber: standby is up and running pg_createsubscriber: stopping the server to start the transformation steps 2024-03-07 14:27:10.290 UTC [29689][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:10.290 UTC [29689][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:10.297 UTC [29701][checkpointer] LOG: shutting down 2024-03-07 14:27:10.297 UTC [29701][checkpointer] LOG: restartpoint starting: shutdown immediate 2024-03-07 14:27:10.297 UTC [29701][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-07 14:27:10.297 UTC [29701][checkpointer] LOG: recovery restart point at 0/3008C98 2024-03-07 14:27:10.302 UTC [29689][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: starting the standby with command-line options 2024-03-07 14:27:10.453 UTC [29835][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-07 14:27:10.453 UTC [29835][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:10.480 UTC [29838][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:10 UTC 2024-03-07 14:27:10.480 UTC [29838][startup] LOG: entering standby mode 2024-03-07 14:27:10.482 UTC [29838][startup] LOG: consistent recovery state reached at 0/3008D10 2024-03-07 14:27:10.482 UTC [29838][startup] LOG: invalid record length at 0/3008D10: expected at least 24, got 0 2024-03-07 14:27:10.482 UTC [29835][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:10.525 UTC [29845][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:10.525 UTC [29838][startup] LOG: redo starts at 0/3008D10 pg_createsubscriber: server was started pg_createsubscriber: checking settings on subscriber 2024-03-07 14:27:10.544 UTC [29855][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:10.544 UTC [29855][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-07 14:27:10.545 UTC [29855][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:10.587 UTC [29855][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:10.596 UTC [29855][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:10.596 UTC [29855][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-07 14:27:10.597 UTC [29855][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-07 14:27:10.608 UTC [29855][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.070 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. [14:27:10.788](0.964s) 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-07 14:27:10.850 UTC [29845][walreceiver] LOG: replication terminated by primary server 2024-03-07 14:27:10.850 UTC [29845][walreceiver] DETAIL: End of WAL reached on timeline 1 at 0/3008DC0. 2024-03-07 14:27:10.850 UTC [29845][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-07 14:27:10.854 UTC [29838][startup] LOG: invalid record length at 0/3008DC0: expected at least 24, got 0 2024-03-07 14:27:10.866 UTC [29892][walreceiver] FATAL: could not connect to the primary server: connection to server on socket "/tmp/UpBJYi7JVt/.s.PGSQL.60895" failed: No such file or directory Is the server running locally and accepting connections on that socket? 2024-03-07 14:27:10.866 UTC [29838][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 29899 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 on subscriber pg_createsubscriber: standby is up and running pg_createsubscriber: stopping the server to start the transformation steps 2024-03-07 14:27:11.146 UTC [29835][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:11.146 UTC [29835][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:11.154 UTC [29836][checkpointer] LOG: shutting down 2024-03-07 14:27:11.154 UTC [29836][checkpointer] LOG: restartpoint starting: shutdown immediate 2024-03-07 14:27:11.155 UTC [29836][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-07 14:27:11.155 UTC [29836][checkpointer] LOG: recovery restart point at 0/3008D48 2024-03-07 14:27:11.164 UTC [29835][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: starting the standby with command-line options 2024-03-07 14:27:11.376 UTC [29982][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-07 14:27:11.376 UTC [29982][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:11.412 UTC [29988][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:11 UTC 2024-03-07 14:27:11.413 UTC [29988][startup] LOG: entering standby mode 2024-03-07 14:27:11.414 UTC [29988][startup] LOG: consistent recovery state reached at 0/3008DC0 2024-03-07 14:27:11.414 UTC [29988][startup] LOG: invalid record length at 0/3008DC0: expected at least 24, got 0 2024-03-07 14:27:11.414 UTC [29982][postmaster] LOG: database system is ready to accept read-only connections pg_createsubscriber: server was started pg_createsubscriber: checking settings on subscriber 2024-03-07 14:27:11.444 UTC [29996][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:11.444 UTC [29996][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-07 14:27:11.445 UTC [29996][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:11.462 UTC [29992][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:11.462 UTC [29988][startup] LOG: redo starts at 0/3008DC0 2024-03-07 14:27:11.486 UTC [29996][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:11.496 UTC [29996][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:11.496 UTC [29996][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-07 14:27:11.498 UTC [29996][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-07 14:27:11.507 UTC [29996][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.065 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_29921" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_29921" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_29921" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_29921" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:11.652 UTC [29982][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:11.652 UTC [29982][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:11.652 UTC [29992][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:11.661 UTC [29986][checkpointer] LOG: shutting down 2024-03-07 14:27:11.666 UTC [29982][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:11.914 UTC [30048][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-07 14:27:11.915 UTC [30048][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:11.933 UTC [30056][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:11 UTC 2024-03-07 14:27:11.933 UTC [30056][startup] LOG: entering standby mode 2024-03-07 14:27:11.935 UTC [30056][startup] LOG: redo starts at 0/3008DC0 2024-03-07 14:27:11.935 UTC [30056][startup] LOG: consistent recovery state reached at 0/3008DF8 2024-03-07 14:27:11.935 UTC [30056][startup] LOG: invalid record length at 0/3008DF8: expected at least 24, got 0 2024-03-07 14:27:11.935 UTC [30048][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-07 14:27:11.962 UTC [30059][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:11.975 UTC [30062][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:11.975 UTC [30062][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-07 14:27:11.975 UTC [30062][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:12.001 UTC [30062][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:12.002 UTC [30062][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-07 14:27:12.004 UTC [30062][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.033 user=postgres database=pg1 host=[local] 2024-03-07 14:27:12.015 UTC [30071][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:12.016 UTC [30071][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-07 14:27:12.016 UTC [30071][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:12.018 UTC [30071][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_29921" on database "pg1" 2024-03-07 14:27:12.018 UTC [30071][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_29921' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_29921" on database "pg1" 2024-03-07 14:27:12.027 UTC [30075][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:12.027 UTC [30075][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-07 14:27:12.027 UTC [30075][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:12.028 UTC [30071][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.014 user=postgres database=pg1 host=[local] 2024-03-07 14:27:12.078 UTC [30075][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_29921" on database "pg2" 2024-03-07 14:27:12.079 UTC [30075][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_29921' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_29921" on database "pg2" 2024-03-07 14:27:12.081 UTC [30075][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-07 14:27:12.120 UTC [30048][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:12.120 UTC [30048][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:12.120 UTC [30059][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:12.130 UTC [30054][checkpointer] LOG: shutting down 2024-03-07 14:27:12.135 UTC [30048][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343627992381789409 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:12.357 UTC [30120][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-07 14:27:12.357 UTC [30120][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:12.405 UTC [30134][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:12 UTC 2024-03-07 14:27:12.406 UTC [30134][startup] LOG: entering standby mode 2024-03-07 14:27:12.407 UTC [30134][startup] LOG: redo starts at 0/3008DC0 2024-03-07 14:27:12.407 UTC [30134][startup] LOG: consistent recovery state reached at 0/3008DF8 2024-03-07 14:27:12.407 UTC [30134][startup] LOG: invalid record length at 0/3008DF8: expected at least 24, got 0 2024-03-07 14:27:12.407 UTC [30120][postmaster] LOG: database system is ready to accept read-only connections pg_createsubscriber: server was started pg_createsubscriber: Done! 2024-03-07 14:27:12.446 UTC [30138][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 [14:27:12.668](1.880s) 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-07 14:27:12.680 UTC [30120][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:12.680 UTC [30120][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:12.684 UTC [30138][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:12.694 UTC [30129][checkpointer] LOG: shutting down 2024-03-07 14:27:12.699 UTC [30120][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 30204 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:13.222 UTC [30284][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-07 14:27:13.222 UTC [30284][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:13.243 UTC [30293][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:12 UTC 2024-03-07 14:27:13.243 UTC [30293][startup] LOG: entering standby mode 2024-03-07 14:27:13.246 UTC [30293][startup] LOG: redo starts at 0/3008DC0 2024-03-07 14:27:13.246 UTC [30293][startup] LOG: consistent recovery state reached at 0/3008DF8 2024-03-07 14:27:13.246 UTC [30284][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:13.248 UTC [30293][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-07 14:27:13.277 UTC [30302][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:13.278 UTC [30302][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-07 14:27:13.278 UTC [30302][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:13.292 UTC [30295][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:13.325 UTC [30302][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:13.328 UTC [30302][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:13.340 UTC [30302][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-07 14:27:13.344 UTC [30302][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. ================================================================= ==30228==ERROR: AddressSanitizer: heap-use-after-free on address 0x61a000001458 at pc 0x7f9dde683dce bp 0x7ffd2f623720 sp 0x7ffd2f623718 READ of size 4 at 0x61a000001458 thread T0 2024-03-07 14:27:13.364 UTC [30302][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.088 user=postgres database=pg1 host=[local] #0 0x7f9dde683dcd in sendTerminateConn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502 #1 0x7f9dde68542e in pqClosePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4528 #2 0x7f9dde68559c in PQfinish /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4566 #3 0x55949b7fadf1 in disconnect_database /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:446 #4 0x55949b7fc92d in check_subscriber /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:959 #5 0x55949b8002cb in main /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:1977 #6 0x7f9dde484d09 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x23d09) #7 0x55949b7fa869 in _start (/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_createsubscriber+0xd869) 0x61a000001458 is located 472 bytes inside of 1192-byte region [0x61a000001280,0x61a000001728) freed by thread T0 here: #0 0x7f9dde7c0b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123 #1 0x7f9dde684f3b in freePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4406 previously allocated by thread T0 here: #0 0x7f9dde7c0e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145 #1 0x7f9dde685080 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 ==30228==ABORTING [14:27:13.529](0.861s) ok 9 - max_logical_replication_workers is not sufficient ### Restarting node "node_s" # Running: pg_ctl -w -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -l /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/log/041_tests_node_s.log restart 2024-03-07 14:27:13.558 UTC [30284][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:13.558 UTC [30284][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:13.558 UTC [30295][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:13.563 UTC [30290][checkpointer] LOG: shutting down waiting for server to shut down....2024-03-07 14:27:13.569 UTC [30284][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 30373 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:14.151 UTC [30452][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-07 14:27:14.151 UTC [30452][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:14.161 UTC [30461][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:13 UTC 2024-03-07 14:27:14.161 UTC [30461][startup] LOG: entering standby mode 2024-03-07 14:27:14.163 UTC [30461][startup] LOG: redo starts at 0/3008DC0 2024-03-07 14:27:14.163 UTC [30461][startup] LOG: consistent recovery state reached at 0/3008DF8 2024-03-07 14:27:14.163 UTC [30452][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:14.163 UTC [30461][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-07 14:27:14.203 UTC [30463][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:14.203 UTC [30469][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:14.209 UTC [30469][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-07 14:27:14.209 UTC [30469][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:14.225 UTC [30469][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:14.226 UTC [30469][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:14.226 UTC [30469][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-07 14:27:14.227 UTC [30469][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-07 14:27:14.237 UTC [30469][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.034 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_30396" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_30396" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_30396" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_30396" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:14.350 UTC [30452][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:14.350 UTC [30452][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:14.351 UTC [30463][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:14.361 UTC [30459][checkpointer] LOG: shutting down 2024-03-07 14:27:14.367 UTC [30452][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:14.550 UTC [30524][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-07 14:27:14.550 UTC [30524][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:14.563 UTC [30534][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:14 UTC 2024-03-07 14:27:14.563 UTC [30534][startup] LOG: entering standby mode 2024-03-07 14:27:14.564 UTC [30534][startup] LOG: redo starts at 0/3008DC0 2024-03-07 14:27:14.564 UTC [30534][startup] LOG: consistent recovery state reached at 0/3008DF8 2024-03-07 14:27:14.564 UTC [30534][startup] LOG: invalid record length at 0/3008DF8: expected at least 24, got 0 2024-03-07 14:27:14.567 UTC [30524][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:14.611 UTC [30537][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-07 14:27:14.618 UTC [30545][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:14.618 UTC [30545][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-07 14:27:14.618 UTC [30545][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:14.635 UTC [30545][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:14.636 UTC [30545][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-07 14:27:14.637 UTC [30545][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.019 user=postgres database=pg1 host=[local] 2024-03-07 14:27:14.645 UTC [30550][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:14.646 UTC [30550][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-07 14:27:14.646 UTC [30550][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:14.652 UTC [30550][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_30396" on database "pg1" 2024-03-07 14:27:14.653 UTC [30550][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_30396' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_30396" on database "pg1" 2024-03-07 14:27:14.657 UTC [30550][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.011 user=postgres database=pg1 host=[local] 2024-03-07 14:27:14.662 UTC [30552][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:14.663 UTC [30552][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-07 14:27:14.663 UTC [30552][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:14.681 UTC [30552][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_30396" on database "pg2" 2024-03-07 14:27:14.690 UTC [30552][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_30396' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_30396" on database "pg2" 2024-03-07 14:27:14.693 UTC [30552][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.030 user=postgres database=pg2 host=[local] pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1" pg_createsubscriber: stopping the subscriber 2024-03-07 14:27:14.713 UTC [30524][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:14.713 UTC [30524][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:14.719 UTC [30537][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:14.723 UTC [30532][checkpointer] LOG: shutting down 2024-03-07 14:27:14.728 UTC [30524][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343628003369662140 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:14.891 UTC [30623][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-07 14:27:14.892 UTC [30623][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:14.902 UTC [30651][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:14 UTC 2024-03-07 14:27:14.903 UTC [30651][startup] LOG: entering standby mode 2024-03-07 14:27:14.904 UTC [30651][startup] LOG: redo starts at 0/3008DC0 2024-03-07 14:27:14.904 UTC [30651][startup] LOG: consistent recovery state reached at 0/3008DF8 2024-03-07 14:27:14.904 UTC [30651][startup] LOG: invalid record length at 0/3008DF8: expected at least 24, got 0 2024-03-07 14:27:14.909 UTC [30623][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:14.935 UTC [30659][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 pg_createsubscriber: server was started pg_createsubscriber: Done! [14:27:15.407](1.877s) 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-07 14:27:15.464 UTC [30659][walreceiver] LOG: replication terminated by primary server 2024-03-07 14:27:15.464 UTC [30659][walreceiver] DETAIL: End of WAL reached on timeline 1 at 0/3008E70. 2024-03-07 14:27:15.464 UTC [30659][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-07 14:27:15.468 UTC [30651][startup] LOG: invalid record length at 0/3008E70: expected at least 24, got 0 2024-03-07 14:27:15.488 UTC [30744][walreceiver] FATAL: could not connect to the primary server: connection to server on socket "/tmp/UpBJYi7JVt/.s.PGSQL.60895" failed: No such file or directory Is the server running locally and accepting connections on that socket? 2024-03-07 14:27:15.488 UTC [30651][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 30751 2024-03-07 14:27:16.026 UTC [30811][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 2024-03-07 14:27:16.750 UTC [30623][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:16.750 UTC [30623][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:16.758 UTC [30811][walreceiver] FATAL: terminating walreceiver process due to administrator command waiting for server to shut down....2024-03-07 14:27:16.762 UTC [30649][checkpointer] LOG: shutting down 2024-03-07 14:27:16.762 UTC [30649][checkpointer] LOG: restartpoint starting: shutdown immediate 2024-03-07 14:27:16.763 UTC [30649][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-07 14:27:16.763 UTC [30649][checkpointer] LOG: recovery restart point at 0/3008DF8 2024-03-07 14:27:16.768 UTC [30623][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 30919 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:17.538 UTC [31017][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-07 14:27:17.538 UTC [31017][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:17.576 UTC [31028][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:17 UTC 2024-03-07 14:27:17.577 UTC [31028][startup] LOG: entering standby mode 2024-03-07 14:27:17.578 UTC [31028][startup] LOG: redo starts at 0/3008E70 2024-03-07 14:27:17.578 UTC [31028][startup] LOG: consistent recovery state reached at 0/3008EA8 2024-03-07 14:27:17.578 UTC [31028][startup] LOG: invalid record length at 0/3008EA8: expected at least 24, got 0 2024-03-07 14:27:17.578 UTC [31017][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:17.616 UTC [31032][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-07 14:27:17.660 UTC [31038][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:17.661 UTC [31038][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-07 14:27:17.661 UTC [31038][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:17.710 UTC [31038][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:17.721 UTC [31038][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:17.722 UTC [31038][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-07 14:27:17.724 UTC [31038][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. ================================================================= ==30940==ERROR: AddressSanitizer: heap-use-after-free on address 0x61a000001458 at pc 0x7f48649ecdce bp 0x7ffe5d15d9f0 sp 0x7ffe5d15d9e8 READ of size 4 at 0x61a000001458 thread T0 #0 0x7f48649ecdcd in sendTerminateConn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4502 #1 0x7f48649ee42e in pqClosePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4528 #2 0x7f48649ee59c in PQfinish /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4566 #3 0x55a1d0a24df1 in disconnect_database /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:446 #4 0x55a1d0a26981 in check_subscriber /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:968 #5 0x55a1d0a2a2cb in main /tmp/cirrus-ci-build/src/bin/pg_basebackup/pg_createsubscriber.c:1977 #6 0x7f48647edd09 in __libc_start_main (/lib/x86_64-linux-gnu/libc.so.6+0x23d09) #7 0x55a1d0a24869 in _start (/tmp/cirrus-ci-build/tmp_install/usr/local/pgsql/bin/pg_createsubscriber+0xd869) 0x61a000001458 is located 472 bytes inside of 1192-byte region [0x61a000001280,0x61a000001728) freed by thread T0 here: #0 0x7f4864b29b6f in __interceptor_free ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:123 #1 0x7f48649edf3b in freePGconn /tmp/cirrus-ci-build/src/interfaces/libpq/fe-connect.c:4406 previously allocated by thread T0 here: #0 0x7f4864b29e8f in __interceptor_malloc ../../../../src/libsanitizer/asan/asan_malloc_linux.cpp:145 #1 0x7f48649ee080 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 2024-03-07 14:27:17.750 UTC [31038][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.091 user=postgres database=pg1 host=[local] 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 ==30940==ABORTING [14:27:18.112](2.705s) 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-07 14:27:18.168 UTC [31032][walreceiver] LOG: replication terminated by primary server 2024-03-07 14:27:18.168 UTC [31032][walreceiver] DETAIL: End of WAL reached on timeline 1 at 0/3008F20. 2024-03-07 14:27:18.168 UTC [31032][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-07 14:27:18.172 UTC [31028][startup] LOG: invalid record length at 0/3008F20: expected at least 24, got 0 2024-03-07 14:27:18.182 UTC [31103][walreceiver] FATAL: could not connect to the primary server: connection to server on socket "/tmp/UpBJYi7JVt/.s.PGSQL.60895" failed: No such file or directory Is the server running locally and accepting connections on that socket? 2024-03-07 14:27:18.182 UTC [31028][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 31113 2024-03-07 14:27:18.701 UTC [31164][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:18.704 UTC [31028][startup] WARNING: hot standby is not possible because of insufficient parameter settings 2024-03-07 14:27:18.704 UTC [31028][startup] DETAIL: max_worker_processes = 2 is a lower setting than on the primary server, where its value was 3. 2024-03-07 14:27:18.704 UTC [31028][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-07 14:27:18.704 UTC [31028][startup] LOG: recovery has paused 2024-03-07 14:27:18.704 UTC [31028][startup] DETAIL: If recovery is unpaused, the server will shut down. 2024-03-07 14:27:18.704 UTC [31028][startup] HINT: You can then restart the server after making the necessary configuration changes. 2024-03-07 14:27:18.704 UTC [31028][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-07 14:27:19.463 UTC [31017][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:19.463 UTC [31017][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:19.463 UTC [31164][walreceiver] FATAL: terminating walreceiver process due to administrator command waiting for server to shut down....2024-03-07 14:27:19.708 UTC [31026][checkpointer] LOG: shutting down 2024-03-07 14:27:19.708 UTC [31026][checkpointer] LOG: restartpoint starting: shutdown immediate 2024-03-07 14:27:19.709 UTC [31026][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-07 14:27:19.709 UTC [31026][checkpointer] LOG: recovery restart point at 0/3008EA8 2024-03-07 14:27:19.713 UTC [31017][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 31318 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:20.251 UTC [31378][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-07 14:27:20.252 UTC [31378][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:20.272 UTC [31386][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:20 UTC 2024-03-07 14:27:20.272 UTC [31386][startup] LOG: entering standby mode 2024-03-07 14:27:20.274 UTC [31386][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:20.274 UTC [31386][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:20.274 UTC [31378][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:20.274 UTC [31386][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:20.287 UTC [31390][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-07 14:27:20.304 UTC [31395][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:20.305 UTC [31395][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-07 14:27:20.305 UTC [31395][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:20.336 UTC [31395][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:20.337 UTC [31395][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:20.337 UTC [31395][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-07 14:27:20.339 UTC [31395][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-07 14:27:20.351 UTC [31395][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_31332" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_31332" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_31332" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_31332" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:20.551 UTC [31378][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:20.551 UTC [31378][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:20.551 UTC [31390][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:20.560 UTC [31384][checkpointer] LOG: shutting down 2024-03-07 14:27:20.565 UTC [31378][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:20.735 UTC [31478][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-07 14:27:20.735 UTC [31478][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:20.764 UTC [31482][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:20 UTC 2024-03-07 14:27:20.764 UTC [31482][startup] LOG: entering standby mode 2024-03-07 14:27:20.766 UTC [31482][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:20.766 UTC [31482][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:20.766 UTC [31478][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:20.767 UTC [31482][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:20.803 UTC [31483][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-07 14:27:20.826 UTC [31489][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:20.827 UTC [31489][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-07 14:27:20.827 UTC [31489][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:20.841 UTC [31489][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:20.842 UTC [31489][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-07 14:27:20.845 UTC [31494][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:20.846 UTC [31494][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-07 14:27:20.846 UTC [31494][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:20.856 UTC [31489][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.029 user=postgres database=pg1 host=[local] 2024-03-07 14:27:20.858 UTC [31494][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_31332" on database "pg1" 2024-03-07 14:27:20.859 UTC [31494][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_31332' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_31332" on database "pg1" 2024-03-07 14:27:20.861 UTC [31494][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.015 user=postgres database=pg1 host=[local] 2024-03-07 14:27:20.872 UTC [31496][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:20.873 UTC [31496][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-07 14:27:20.873 UTC [31496][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:20.897 UTC [31496][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_31332" on database "pg2" 2024-03-07 14:27:20.898 UTC [31496][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_31332' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_31332" on database "pg2" 2024-03-07 14:27:20.901 UTC [31496][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.031 user=postgres database=pg2 host=[local] pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1" pg_createsubscriber: stopping the subscriber 2024-03-07 14:27:20.941 UTC [31478][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:20.941 UTC [31478][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:20.942 UTC [31483][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:20.947 UTC [31480][checkpointer] LOG: shutting down 2024-03-07 14:27:20.952 UTC [31478][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343628030283491940 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:21.161 UTC [31539][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-07 14:27:21.161 UTC [31539][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:21.200 UTC [31548][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:20 UTC 2024-03-07 14:27:21.200 UTC [31548][startup] LOG: entering standby mode 2024-03-07 14:27:21.202 UTC [31548][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:21.202 UTC [31548][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:21.202 UTC [31548][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:21.202 UTC [31539][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:21.227 UTC [31562][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 pg_createsubscriber: server was started pg_createsubscriber: Done! [14:27:21.519](3.407s) 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/UpBJYi7JVt -p 60896 --checkpoint fast --no-sync 2024-03-07 14:27:21.559 UTC [31613][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:21.561 UTC [31613][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-07 14:27:21.561 UTC [31613][walsender] [[unknown]][17/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:21.561 UTC [31613][walsender] [041_tests.pl][17/0:0] LOG: received replication command: SHOW data_directory_mode 2024-03-07 14:27:21.561 UTC [31613][walsender] [041_tests.pl][17/0:0] STATEMENT: SHOW data_directory_mode 2024-03-07 14:27:21.562 UTC [31613][walsender] [041_tests.pl][17/0:0] LOG: received replication command: SHOW wal_segment_size 2024-03-07 14:27:21.562 UTC [31613][walsender] [041_tests.pl][17/0:0] STATEMENT: SHOW wal_segment_size 2024-03-07 14:27:21.562 UTC [31613][walsender] [041_tests.pl][17/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:21.562 UTC [31613][walsender] [041_tests.pl][17/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:21.562 UTC [31613][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-07 14:27:21.562 UTC [31613][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-07 14:27:21.592 UTC [31619][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:21.593 UTC [31619][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-07 14:27:21.593 UTC [31619][walsender] [[unknown]][18/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:21.600 UTC [31619][walsender] [041_tests.pl][18/0:0] LOG: received replication command: SHOW data_directory_mode 2024-03-07 14:27:21.600 UTC [31619][walsender] [041_tests.pl][18/0:0] STATEMENT: SHOW data_directory_mode 2024-03-07 14:27:21.600 UTC [31619][walsender] [041_tests.pl][18/0:0] LOG: received replication command: CREATE_REPLICATION_SLOT "pg_basebackup_31619" TEMPORARY PHYSICAL ( RESERVE_WAL) 2024-03-07 14:27:21.600 UTC [31619][walsender] [041_tests.pl][18/0:0] STATEMENT: CREATE_REPLICATION_SLOT "pg_basebackup_31619" TEMPORARY PHYSICAL ( RESERVE_WAL) 2024-03-07 14:27:21.600 UTC [31619][walsender] [041_tests.pl][18/0:0] LOG: released physical replication slot "pg_basebackup_31619" 2024-03-07 14:27:21.600 UTC [31619][walsender] [041_tests.pl][18/0:0] STATEMENT: CREATE_REPLICATION_SLOT "pg_basebackup_31619" TEMPORARY PHYSICAL ( RESERVE_WAL) 2024-03-07 14:27:21.612 UTC [31619][walsender] [041_tests.pl][18/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:21.612 UTC [31619][walsender] [041_tests.pl][18/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:21.612 UTC [31619][walsender] [041_tests.pl][18/0:0] LOG: received replication command: START_REPLICATION SLOT "pg_basebackup_31619" 0/3000000 TIMELINE 1 2024-03-07 14:27:21.612 UTC [31619][walsender] [041_tests.pl][18/0:0] STATEMENT: START_REPLICATION SLOT "pg_basebackup_31619" 0/3000000 TIMELINE 1 2024-03-07 14:27:21.612 UTC [31619][walsender] [041_tests.pl][18/0:0] LOG: acquired physical replication slot "pg_basebackup_31619" 2024-03-07 14:27:21.612 UTC [31619][walsender] [041_tests.pl][18/0:0] STATEMENT: START_REPLICATION SLOT "pg_basebackup_31619" 0/3000000 TIMELINE 1 2024-03-07 14:27:21.870 UTC [31619][walsender] [041_tests.pl][18/0:0] LOG: released physical replication slot "pg_basebackup_31619" 2024-03-07 14:27:21.870 UTC [31619][walsender] [041_tests.pl][18/0:0] STATEMENT: START_REPLICATION SLOT "pg_basebackup_31619" 0/3000000 TIMELINE 1 2024-03-07 14:27:21.870 UTC [31613][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.312 user=postgres database= host=[local] 2024-03-07 14:27:21.872 UTC [31619][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.287 user=postgres database= host=[local] # Backup finished # Checking port 60897 # Found port 60897 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=60897 host=/tmp/UpBJYi7JVt 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.... done server started # Postmaster PID for node "node_c" is 31729 # 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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60896 --database pg1 --database pg2 2024-03-07 14:27:22.410 UTC [31743][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:22.411 UTC [31743][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-07 14:27:22.411 UTC [31743][walsender] [[unknown]][19/1:0] LOG: replication connection authorized: user=postgres application_name=node_c 2024-03-07 14:27:22.416 UTC [31743][walsender] [node_c][19/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:22.416 UTC [31743][walsender] [node_c][19/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:22.417 UTC [31743][walsender] [node_c][19/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.417 UTC [31743][walsender] [node_c][19/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.417 UTC [31743][walsender] [node_c][19/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:22.417 UTC [31743][walsender] [node_c][19/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.421 UTC [31743][walsender] [node_c][:0] LOG: disconnection: session time: 0:00:00.017 user=postgres database= host=[local] pg_createsubscriber: validating connection string on publisher pg_createsubscriber: validating connection string on subscriber 2024-03-07 14:27:22.436 UTC [31757][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:22.437 UTC [31757][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-07 14:27:22.437 UTC [31757][walsender] [[unknown]][20/1:0] LOG: replication connection authorized: user=postgres application_name=node_c 2024-03-07 14:27:22.438 UTC [31757][walsender] [node_c][20/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:22.438 UTC [31757][walsender] [node_c][20/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:22.439 UTC [31757][walsender] [node_c][20/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.439 UTC [31757][walsender] [node_c][20/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.439 UTC [31757][walsender] [node_c][20/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:22.439 UTC [31757][walsender] [node_c][20/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.444 UTC [31757][walsender] [node_c][:0] LOG: disconnection: session time: 0:00:00.008 user=postgres database= host=[local] 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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 on subscriber pg_createsubscriber: standby is up and running pg_createsubscriber: stopping the server to start the transformation steps 2024-03-07 14:27:22.493 UTC [31539][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:22.493 UTC [31539][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:22.493 UTC [31562][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:22.499 UTC [31546][checkpointer] LOG: shutting down 2024-03-07 14:27:22.504 UTC [31539][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: starting the standby with command-line options 2024-03-07 14:27:22.751 UTC [31795][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-07 14:27:22.751 UTC [31795][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:22.780 UTC [31805][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:22 UTC 2024-03-07 14:27:22.780 UTC [31805][startup] LOG: entering standby mode 2024-03-07 14:27:22.782 UTC [31805][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:22.782 UTC [31805][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:22.782 UTC [31805][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:22.782 UTC [31795][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:22.825 UTC [31808][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-07 14:27:22.890 UTC [31821][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:22.891 UTC [31821][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-07 14:27:22.891 UTC [31821][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:22.919 UTC [31821][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:22.920 UTC [31821][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:22.920 UTC [31821][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-07 14:27:22.921 UTC [31821][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-07 14:27:22.926 UTC [31821][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.035 user=postgres database=pg1 host=[local] 2024-03-07 14:27:22.930 UTC [31827][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:22.940 UTC [31827][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-07 14:27:22.940 UTC [31827][walsender] [[unknown]][17/1:0] LOG: replication connection authorized: user=postgres application_name=node_c 2024-03-07 14:27:22.941 UTC [31827][walsender] [node_c][17/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:22.941 UTC [31827][walsender] [node_c][17/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:22.941 UTC [31827][walsender] [node_c][17/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.941 UTC [31827][walsender] [node_c][17/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.941 UTC [31827][walsender] [node_c][17/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:22.941 UTC [31827][walsender] [node_c][17/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:22.941 UTC [31827][walsender] [node_c][:0] LOG: disconnection: session time: 0:00:00.011 user=postgres database= 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_31742" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_31742" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_31742" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_31742" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:23.096 UTC [31795][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:23.096 UTC [31795][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:23.100 UTC [31808][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:23.107 UTC [31803][checkpointer] LOG: shutting down 2024-03-07 14:27:23.113 UTC [31795][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:23.370 UTC [31879][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-07 14:27:23.370 UTC [31879][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:23.394 UTC [31887][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:23 UTC 2024-03-07 14:27:23.394 UTC [31887][startup] LOG: entering standby mode 2024-03-07 14:27:23.395 UTC [31887][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:23.396 UTC [31887][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:23.396 UTC [31887][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:23.396 UTC [31879][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-07 14:27:23.420 UTC [31894][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:23.425 UTC [31894][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-07 14:27:23.425 UTC [31894][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:23.435 UTC [31889][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 2024-03-07 14:27:23.456 UTC [31894][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:23.456 UTC [31900][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:23.457 UTC [31900][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-07 14:27:23.457 UTC [31900][walsender] [[unknown]][17/1:0] LOG: replication connection authorized: user=postgres application_name=node_c 2024-03-07 14:27:23.457 UTC [31900][walsender] [node_c][17/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:23.457 UTC [31900][walsender] [node_c][17/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:23.457 UTC [31900][walsender] [node_c][17/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:23.457 UTC [31900][walsender] [node_c][17/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:23.457 UTC [31900][walsender] [node_c][17/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:23.457 UTC [31900][walsender] [node_c][17/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:23.458 UTC [31894][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-07 14:27:23.464 UTC [31894][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.046 user=postgres database=pg1 host=[local] 2024-03-07 14:27:23.465 UTC [31900][walsender] [node_c][:0] LOG: disconnection: session time: 0:00:00.021 user=postgres database= host=[local] 2024-03-07 14:27:23.499 UTC [31906][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:23.500 UTC [31906][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-07 14:27:23.501 UTC [31906][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:23.502 UTC [31906][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_31742" on database "pg1" 2024-03-07 14:27:23.508 UTC [31906][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_31742' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_31742" on database "pg1" 2024-03-07 14:27:23.511 UTC [31906][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.016 user=postgres database=pg1 host=[local] 2024-03-07 14:27:23.524 UTC [31913][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:23.525 UTC [31913][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-07 14:27:23.525 UTC [31913][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:23.570 UTC [31913][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_31742" on database "pg2" 2024-03-07 14:27:23.571 UTC [31913][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_31742' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_31742" on database "pg2" 2024-03-07 14:27:23.572 UTC [31913][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.048 user=postgres database=pg2 host=[local] pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1" pg_createsubscriber: stopping the subscriber 2024-03-07 14:27:23.592 UTC [31879][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:23.592 UTC [31879][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:23.596 UTC [31889][walreceiver] FATAL: terminating walreceiver process due to administrator command 2024-03-07 14:27:23.601 UTC [31885][checkpointer] LOG: shutting down 2024-03-07 14:27:23.607 UTC [31879][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343628041556941822 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:23.800 UTC [31946][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-07 14:27:23.800 UTC [31946][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60896" 2024-03-07 14:27:23.829 UTC [31952][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:23 UTC 2024-03-07 14:27:23.829 UTC [31952][startup] LOG: entering standby mode 2024-03-07 14:27:23.831 UTC [31952][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:23.831 UTC [31952][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:23.831 UTC [31952][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:23.831 UTC [31946][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:23.860 UTC [31961][walreceiver] LOG: started streaming WAL from primary at 0/3000000 on timeline 1 pg_createsubscriber: server was started pg_createsubscriber: Done! 2024-03-07 14:27:23.959 UTC [31973][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:23.960 UTC [31973][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-07 14:27:23.960 UTC [31973][walsender] [[unknown]][17/1:0] LOG: replication connection authorized: user=postgres application_name=node_c 2024-03-07 14:27:23.961 UTC [31973][walsender] [node_c][17/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:23.961 UTC [31973][walsender] [node_c][17/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:23.961 UTC [31973][walsender] [node_c][17/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:23.961 UTC [31973][walsender] [node_c][17/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:23.961 UTC [31973][walsender] [node_c][17/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:23.961 UTC [31973][walsender] [node_c][17/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:23.965 UTC [31973][walsender] [node_c][:0] LOG: disconnection: session time: 0:00:00.014 user=postgres database= host=[local] [14:27:24.048](2.529s) not ok 13 - standby server is primary to other node [14:27:24.048](0.000s) [14:27:24.048](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=60895 host=/tmp/UpBJYi7JVt dbname='pg1' --socket-directory /tmp/UpBJYi7JVt --subscriber-port 60897 --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 7343627619925293117 on publisher pg_createsubscriber: getting system identifier from subscriber pg_createsubscriber: system identifier is 7343627619925293117 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-07 14:27:24.197 UTC [32008][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-07 14:27:24.197 UTC [32008][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60897" 2024-03-07 14:27:24.203 UTC [32012][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:24 UTC 2024-03-07 14:27:24.203 UTC [32012][startup] LOG: entering standby mode 2024-03-07 14:27:24.204 UTC [32012][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:24.204 UTC [32012][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:24.204 UTC [32012][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:24.204 UTC [32008][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:24.212 UTC [32014][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.213 UTC [32014][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-07 14:27:24.213 UTC [32014][walsender] [[unknown]][18/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:24.213 UTC [32014][walsender] [041_tests.pl][18/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:24.213 UTC [32014][walsender] [041_tests.pl][18/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:24.213 UTC [32014][walsender] [041_tests.pl][18/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.213 UTC [32014][walsender] [041_tests.pl][18/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.213 UTC [32014][walsender] [041_tests.pl][18/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.213 UTC [32014][walsender] [041_tests.pl][18/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.213 UTC [32013][walreceiver] FATAL: could not start WAL streaming: ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.217 UTC [32014][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.006 user=postgres database= host=[local] 2024-03-07 14:27:24.268 UTC [32018][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.269 UTC [32018][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-07 14:27:24.269 UTC [32018][walsender] [[unknown]][19/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:24.269 UTC [32018][walsender] [041_tests.pl][19/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:24.269 UTC [32018][walsender] [041_tests.pl][19/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:24.269 UTC [32018][walsender] [041_tests.pl][19/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.269 UTC [32018][walsender] [041_tests.pl][19/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.269 UTC [32018][walsender] [041_tests.pl][19/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.269 UTC [32018][walsender] [041_tests.pl][19/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.269 UTC [32016][walreceiver] FATAL: could not start WAL streaming: ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.273 UTC [32012][startup] LOG: waiting for WAL to become available at 0/3002000 2024-03-07 14:27:24.273 UTC [32018][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.013 user=postgres database= host=[local] pg_createsubscriber: server was started pg_createsubscriber: checking settings on subscriber 2024-03-07 14:27:24.300 UTC [32021][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.301 UTC [32021][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-07 14:27:24.301 UTC [32021][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:24.328 UTC [32021][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:24.329 UTC [32021][client backend] [041_tests.pl][0/3:0] LOG: statement: SELECT pg_catalog.pg_is_in_recovery() 2024-03-07 14:27:24.329 UTC [32021][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-07 14:27:24.332 UTC [32021][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-07 14:27:24.337 UTC [32021][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.041 user=postgres database=pg1 host=[local] pg_createsubscriber: primary has replication slot "physical_slot" pg_createsubscriber: creating publication "pg_createsubscriber_16384" on database "pg1" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16384_31981" on database "pg1" pg_createsubscriber: create replication slot "pg_createsubscriber_16384_31981" on publisher pg_createsubscriber: creating publication "pg_createsubscriber_16385" on database "pg2" pg_createsubscriber: creating the replication slot "pg_createsubscriber_16385_31981" on database "pg2" pg_createsubscriber: create replication slot "pg_createsubscriber_16385_31981" on publisher pg_createsubscriber: stopping and starting the subscriber 2024-03-07 14:27:24.427 UTC [32008][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:24.427 UTC [32008][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:24.436 UTC [32010][checkpointer] LOG: shutting down 2024-03-07 14:27:24.441 UTC [32008][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped 2024-03-07 14:27:24.608 UTC [32069][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-07 14:27:24.608 UTC [32069][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60897" 2024-03-07 14:27:24.639 UTC [32076][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:24 UTC 2024-03-07 14:27:24.639 UTC [32076][startup] LOG: entering standby mode 2024-03-07 14:27:24.640 UTC [32076][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:24.640 UTC [32076][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:24.641 UTC [32076][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:24.644 UTC [32069][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:24.666 UTC [32080][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.666 UTC [32080][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-07 14:27:24.667 UTC [32080][walsender] [[unknown]][20/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:24.670 UTC [32080][walsender] [041_tests.pl][20/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:24.670 UTC [32080][walsender] [041_tests.pl][20/0:0] STATEMENT: IDENTIFY_SYSTEM pg_createsubscriber: server was started pg_createsubscriber: waiting for the target server to reach the consistent state 2024-03-07 14:27:24.673 UTC [32080][walsender] [041_tests.pl][20/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.673 UTC [32080][walsender] [041_tests.pl][20/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.675 UTC [32080][walsender] [041_tests.pl][20/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.675 UTC [32080][walsender] [041_tests.pl][20/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.675 UTC [32078][walreceiver] FATAL: could not start WAL streaming: ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.680 UTC [32080][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.014 user=postgres database= host=[local] 2024-03-07 14:27:24.685 UTC [32082][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.686 UTC [32082][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-07 14:27:24.686 UTC [32082][client backend] [[unknown]][0/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:24.701 UTC [32086][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.702 UTC [32086][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-07 14:27:24.702 UTC [32086][walsender] [[unknown]][21/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:24.712 UTC [32082][client backend] [041_tests.pl][0/2:0] LOG: statement: SELECT pg_catalog.set_config('search_path', '', false); 2024-03-07 14:27:24.715 UTC [32082][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-07 14:27:24.716 UTC [32082][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.031 user=postgres database=pg1 host=[local] 2024-03-07 14:27:24.716 UTC [32086][walsender] [041_tests.pl][21/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:24.716 UTC [32086][walsender] [041_tests.pl][21/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:24.716 UTC [32086][walsender] [041_tests.pl][21/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.716 UTC [32086][walsender] [041_tests.pl][21/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.716 UTC [32086][walsender] [041_tests.pl][21/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.716 UTC [32086][walsender] [041_tests.pl][21/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:24.716 UTC [32085][walreceiver] FATAL: could not start WAL streaming: ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:24.716 UTC [32086][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.015 user=postgres database= host=[local] 2024-03-07 14:27:24.720 UTC [32076][startup] LOG: waiting for WAL to become available at 0/3002000 2024-03-07 14:27:24.723 UTC [32089][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.723 UTC [32089][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-07 14:27:24.723 UTC [32089][client backend] [[unknown]][1/1:0] LOG: connection authorized: user=postgres database=pg1 application_name=041_tests.pl 2024-03-07 14:27:24.725 UTC [32089][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_31981" on database "pg1" 2024-03-07 14:27:24.725 UTC [32089][client backend] [041_tests.pl][1/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16384_31981' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg1" pg_createsubscriber: enabling subscription "pg_createsubscriber_16384_31981" on database "pg1" 2024-03-07 14:27:24.727 UTC [32089][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.004 user=postgres database=pg1 host=[local] 2024-03-07 14:27:24.748 UTC [32092][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:24.749 UTC [32092][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-07 14:27:24.749 UTC [32092][client backend] [[unknown]][2/1:0] LOG: connection authorized: user=postgres database=pg2 application_name=041_tests.pl 2024-03-07 14:27:24.777 UTC [32092][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_31981" on database "pg2" 2024-03-07 14:27:24.778 UTC [32092][client backend] [041_tests.pl][2/3:0] LOG: statement: SELECT oid FROM pg_catalog.pg_subscription WHERE subname = 'pg_createsubscriber_16385_31981' pg_createsubscriber: setting the replication progress (node name "pg_0" ; LSN 0/0) on database "pg2" pg_createsubscriber: enabling subscription "pg_createsubscriber_16385_31981" on database "pg2" 2024-03-07 14:27:24.784 UTC [32092][client backend] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.040 user=postgres database=pg2 host=[local] pg_createsubscriber: dropping the replication slot "physical_slot" on database "pg1" pg_createsubscriber: stopping the subscriber 2024-03-07 14:27:24.832 UTC [32069][postmaster] LOG: received fast shutdown request 2024-03-07 14:27:24.832 UTC [32069][postmaster] LOG: aborting any active transactions 2024-03-07 14:27:24.837 UTC [32074][checkpointer] LOG: shutting down 2024-03-07 14:27:24.842 UTC [32069][postmaster] LOG: database system is shut down pg_createsubscriber: server was stopped pg_createsubscriber: modifying system identifier from subscriber pg_createsubscriber: system identifier is 7343628046796705005 on subscriber pg_createsubscriber: running pg_resetwal on the subscriber 2024-03-07 14:27:25.074 UTC [32130][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-07 14:27:25.074 UTC [32130][postmaster] LOG: listening on Unix socket "/tmp/UpBJYi7JVt/.s.PGSQL.60897" 2024-03-07 14:27:25.092 UTC [32139][startup] LOG: database system was shut down in recovery at 2024-03-07 14:27:24 UTC 2024-03-07 14:27:25.092 UTC [32139][startup] LOG: entering standby mode 2024-03-07 14:27:25.094 UTC [32139][startup] LOG: redo starts at 0/3008F20 2024-03-07 14:27:25.094 UTC [32139][startup] LOG: consistent recovery state reached at 0/3008F58 2024-03-07 14:27:25.094 UTC [32130][postmaster] LOG: database system is ready to accept read-only connections 2024-03-07 14:27:25.094 UTC [32139][startup] LOG: invalid record length at 0/3008F58: expected at least 24, got 0 2024-03-07 14:27:25.101 UTC [32147][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:25.102 UTC [32147][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-07 14:27:25.102 UTC [32147][walsender] [[unknown]][22/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:25.102 UTC [32147][walsender] [041_tests.pl][22/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:25.102 UTC [32147][walsender] [041_tests.pl][22/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:25.103 UTC [32147][walsender] [041_tests.pl][22/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:25.103 UTC [32147][walsender] [041_tests.pl][22/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:25.103 UTC [32147][walsender] [041_tests.pl][22/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:25.103 UTC [32147][walsender] [041_tests.pl][22/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:25.103 UTC [32144][walreceiver] FATAL: could not start WAL streaming: ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:25.107 UTC [32147][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.006 user=postgres database= host=[local] 2024-03-07 14:27:25.112 UTC [32149][not initialized] [[unknown]][:0] LOG: connection received: host=[local] 2024-03-07 14:27:25.113 UTC [32149][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-07 14:27:25.113 UTC [32149][walsender] [[unknown]][23/1:0] LOG: replication connection authorized: user=postgres application_name=041_tests.pl 2024-03-07 14:27:25.114 UTC [32149][walsender] [041_tests.pl][23/0:0] LOG: received replication command: IDENTIFY_SYSTEM 2024-03-07 14:27:25.114 UTC [32149][walsender] [041_tests.pl][23/0:0] STATEMENT: IDENTIFY_SYSTEM 2024-03-07 14:27:25.114 UTC [32149][walsender] [041_tests.pl][23/0:0] LOG: received replication command: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:25.114 UTC [32149][walsender] [041_tests.pl][23/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:25.114 UTC [32149][walsender] [041_tests.pl][23/0:0] ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:25.114 UTC [32149][walsender] [041_tests.pl][23/0:0] STATEMENT: START_REPLICATION SLOT "physical_slot" 0/3000000 TIMELINE 1 2024-03-07 14:27:25.114 UTC [32148][walreceiver] FATAL: could not start WAL streaming: ERROR: replication slot "physical_slot" does not exist 2024-03-07 14:27:25.115 UTC [32149][walsender] [041_tests.pl][:0] LOG: disconnection: session time: 0:00:00.002 user=postgres database= host=[local] 2024-03-07 14:27:25.119 UTC [32139][startup] LOG: waiting for WAL to become available at 0/3002000 pg_createsubscriber: server was started pg_createsubscriber: Done! [14:27:25.192](1.144s) not ok 14 - standby server is not direct standby of publisher [14:27:25.192](0.000s) [14:27:25.192](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 2024-03-07 14:27:25.216 UTC [31961][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. waiting for server to shut down... done server stopped # No postmaster PID for node "node_p" ### Stopping node "node_s" using mode immediate # Running: pg_ctl -D /tmp/cirrus-ci-build/src/bin/pg_basebackup/tmp_check/t_041_tests_node_s_data/pgdata -m immediate stop 2024-03-07 14:27:25.235 UTC [31946][postmaster] LOG: received immediate shutdown request waiting for server to shut down....2024-03-07 14:27:25.244 UTC [31946][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-07 14:27:25.369 UTC [32130][postmaster] LOG: received immediate shutdown request 2024-03-07 14:27:25.371 UTC [32130][postmaster] LOG: database system is shut down done server stopped # No postmaster PID for node "node_c" [14:27:25.470](0.278s) 1..14 [14:27:25.472](0.002s) # Looks like you failed 2 tests of 14.