# Checking port 54751 # Found port 54751 Name: publisher Data directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata Backup directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/backup Archive directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/archives Connection string: port=54751 host=C:/Windows/TEMP/weUIV2zECA Log file: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_publisher.log [12:44:08.631](0.115s) # initializing database system by copying initdb template # Running: robocopy /E /NJS /NJH /NFL /NDL /NP C:/cirrus/build/tmp_install/initdb-template C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata # Running: C:\cirrus\build\src/test\regress\pg_regress.exe --config-auth C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata --create-role repl_role ### Starting node "publisher" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_publisher.log -o --cluster-name=publisher start waiting for server to start.... done server started # Postmaster PID for node "publisher" is 7184 # Checking port 54752 # Found port 54752 Name: subscriber1 Data directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber1_data/pgdata Backup directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber1_data/backup Archive directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber1_data/archives Connection string: port=54752 host=C:/Windows/TEMP/weUIV2zECA Log file: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_subscriber1.log [12:44:10.848](2.218s) # initializing database system by copying initdb template # Running: robocopy /E /NJS /NJH /NFL /NDL /NP C:/cirrus/build/tmp_install/initdb-template C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber1_data/pgdata # Running: C:\cirrus\build\src/test\regress\pg_regress.exe --config-auth C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber1_data/pgdata ### Starting node "subscriber1" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber1_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_subscriber1.log -o --cluster-name=subscriber1 start waiting for server to start.... done server started # Postmaster PID for node "subscriber1" is 7464 [12:44:13.541](2.693s) ok 1 - logical slot has failover false on the publisher [12:44:13.907](0.366s) ok 2 - logical slot has failover true on the publisher [12:44:14.232](0.325s) ok 3 - logical slot has failover false on the publisher [12:44:14.643](0.411s) ok 4 - logical slot has failover true on the publisher [12:44:14.842](0.199s) ok 5 - altering failover is not allowed for enabled subscription [12:44:14.927](0.085s) ok 6 - cannot sync slots on a non-standby server # Taking pg_basebackup backup from node "publisher" # Running: pg_basebackup -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/backup/backup -h C:/Windows/TEMP/weUIV2zECA -p 54751 --checkpoint fast --no-sync # Backup finished # Checking port 54753 # Found port 54753 Name: standby1 Data directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata Backup directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/backup Archive directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/archives Connection string: port=54753 host=C:/Windows/TEMP/weUIV2zECA Log file: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby1.log # Initializing node "standby1" from backup "backup" of node "publisher" ### Enabling streaming replication for node "standby1" ### Enabling WAL restore for node "standby1" ### Reloading node "publisher" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata reload server signaled (lsub2_slot,0/3000060) (sb1_slot,) ### Starting node "standby1" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby1.log -o --cluster-name=standby1 start waiting for server to start.... done server started # Postmaster PID for node "standby1" is 1892 Waiting for replication conn regress_mysub1's replay_lsn to pass 0/3000060 on publisher done [12:44:20.377](5.450s) ok 7 - last inactive time for slot lsub1_slot is valid on node publisher Waiting for replication conn standby1's replay_lsn to pass 0/3000060 on publisher done [12:44:20.830](0.453s) ok 8 - logical slots have synced as true on standby [12:44:21.187](0.357s) ok 9 - last inactive time for slot lsub1_slot is valid on node standby1 [12:44:21.750](0.563s) ok 10 - synchronized slot has got its own inactive_since [12:44:23.174](1.424s) ok 11 - synchronized slot has been dropped ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled Waiting for replication conn standby1's replay_lsn to pass 0/40000F8 on publisher done [12:44:24.473](1.299s) ok 12 - synchronized slot has been invalidated ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled #### Begin standard error psql::2: NOTICE: dropped replication slot "lsub1_slot" on publisher psql::3: NOTICE: created replication slot "lsub1_slot" on publisher #### End standard error Waiting for replication conn regress_mysub1's replay_lsn to pass 0/4000130 on publisher done [12:44:26.317](1.844s) ok 13 - last inactive time for slot lsub1_slot is valid on node publisher Waiting for replication conn standby1's replay_lsn to pass 0/4000168 on publisher done [12:44:27.303](0.986s) not ok 14 - logical slot is re-synced [12:44:27.303](0.000s) # Failed test 'logical slot is re-synced' # at C:/cirrus/src/test/recovery/t/040_standby_failover_slots_sync.pl line 311. [12:44:27.303](0.000s) # got: '' # expected: 't' ### Reloading node "publisher" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata reload server signaled ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled [12:44:27.698](0.395s) not ok 15 - logical decoding is not allowed on synced slot [12:44:27.721](0.022s) # Failed test 'logical decoding is not allowed on synced slot' # at C:/cirrus/src/test/recovery/t/040_standby_failover_slots_sync.pl line 333. [12:44:27.962](0.241s) not ok 16 - synced slot on standby cannot be altered [12:44:27.962](0.000s) # Failed test 'synced slot on standby cannot be altered' # at C:/cirrus/src/test/recovery/t/040_standby_failover_slots_sync.pl line 342. [12:44:28.193](0.231s) not ok 17 - synced slot on standby cannot be dropped [12:44:28.194](0.001s) # Failed test 'synced slot on standby cannot be dropped' # at C:/cirrus/src/test/recovery/t/040_standby_failover_slots_sync.pl line 348. ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled [12:44:28.558](0.364s) ok 18 - cannot sync slots if dbname is not specified in primary_conninfo ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled # Taking pg_basebackup backup2 from node "standby1" # Running: pg_basebackup -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/backup/backup2 -h C:/Windows/TEMP/weUIV2zECA -p 54753 --checkpoint fast --no-sync # Backup finished # Checking port 54754 # Found port 54754 Name: cascading_standby Data directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_cascading_standby_data/pgdata Backup directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_cascading_standby_data/backup Archive directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_cascading_standby_data/archives Connection string: port=54754 host=C:/Windows/TEMP/weUIV2zECA Log file: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_cascading_standby.log # Initializing node "cascading_standby" from backup "backup2" of node "standby1" ### Enabling streaming replication for node "cascading_standby" ### Enabling WAL restore for node "cascading_standby" (cascading_sb_slot,) ### Starting node "cascading_standby" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_cascading_standby_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_cascading_standby.log -o --cluster-name=cascading_standby start waiting for server to start.... done server started # Postmaster PID for node "cascading_standby" is 4668 [12:44:42.685](14.127s) ok 19 - cannot sync slots to a cascading standby server ### Stopping node "cascading_standby" using mode fast # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_cascading_standby_data/pgdata -m fast stop waiting for server to shut down.... done server stopped # No postmaster PID for node "cascading_standby" Waiting for replication conn standby1's replay_lsn to pass 0/40002A8 on publisher done [12:44:45.423](2.738s) ok 20 - confirmed_flush_lsn of slot snap_test_slot synced to standby Waiting for replication conn standby1's replay_lsn to pass 0/4432428 on publisher done ### Stopping node "standby1" using mode fast # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -m fast stop waiting for server to shut down.... done server stopped # No postmaster PID for node "standby1" ### Starting node "standby1" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby1.log -o --cluster-name=standby1 start waiting for server to start.... done server started # Postmaster PID for node "standby1" is 6856 ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled ### Reloading node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata reload server signaled Waiting for all subscriptions in "subscriber1" to synchronize data done [12:44:54.777](9.354s) ok 21 - confirmed_flush_lsn of slot lsub1_slot synced to standby (sb2_slot,) # Taking pg_basebackup backup3 from node "publisher" # Running: pg_basebackup -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/backup/backup3 -h C:/Windows/TEMP/weUIV2zECA -p 54751 --checkpoint fast --no-sync # Backup finished # Checking port 54755 # Found port 54755 Name: standby2 Data directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby2_data/pgdata Backup directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby2_data/backup Archive directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby2_data/archives Connection string: port=54755 host=C:/Windows/TEMP/weUIV2zECA Log file: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby2.log # Initializing node "standby2" from backup "backup3" of node "publisher" ### Enabling streaming replication for node "standby2" ### Enabling WAL restore for node "standby2" ### Starting node "standby2" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby2_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby2.log -o --cluster-name=standby2 start waiting for server to start.... done server started # Postmaster PID for node "standby2" is 1000 Waiting for replication conn standby2's replay_lsn to pass 0/6000060 on publisher done ### Reloading node "publisher" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata reload server signaled # Checking port 54756 # Found port 54756 Name: subscriber2 Data directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber2_data/pgdata Backup directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber2_data/backup Archive directory: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber2_data/archives Connection string: port=54756 host=C:/Windows/TEMP/weUIV2zECA Log file: C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_subscriber2.log [12:45:07.904](13.127s) # initializing database system by copying initdb template # Running: robocopy /E /NJS /NJH /NFL /NDL /NP C:/cirrus/build/tmp_install/initdb-template C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber2_data/pgdata # Running: C:\cirrus\build\src/test\regress\pg_regress.exe --config-auth C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber2_data/pgdata ### Starting node "subscriber2" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber2_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_subscriber2.log -o --cluster-name=subscriber2 start waiting for server to start.... done server started # Postmaster PID for node "subscriber2" is 7812 #### Begin standard error psql::3: NOTICE: created replication slot "lsub2_slot" on publisher #### End standard error Waiting for all subscriptions in "subscriber2" to synchronize data done ### Stopping node "standby1" using mode fast # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -m fast stop waiting for server to shut down.... done server stopped # No postmaster PID for node "standby1" Waiting for replication conn standby2's replay_lsn to pass 0/60008A8 on publisher done [12:45:13.214](5.310s) ok 22 - standby2 gets data from primary Waiting for replication conn regress_mysub2's replay_lsn to pass 0/60008A8 on publisher done [12:45:13.871](0.658s) ok 23 - subscriber2 gets data from primary [12:45:13.989](0.118s) ok 24 - subscriber1 doesn't get data from primary until standby1 acknowledges changes ### Starting node "standby1" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby1.log -o --cluster-name=standby1 start waiting for server to start.... done server started # Postmaster PID for node "standby1" is 7716 Waiting for replication conn standby1's replay_lsn to pass 0/60008A8 on publisher done [12:45:15.952](1.962s) ok 25 - standby1 gets data from primary Waiting for replication conn regress_mysub1's replay_lsn to pass 0/60008A8 on publisher done [12:45:16.454](0.502s) ok 26 - subscriber1 gets data from primary after standby1 acknowledges changes Waiting for replication conn regress_mysub1's replay_lsn to pass 0/6004968 on publisher done ### Stopping node "standby1" using mode fast # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -m fast stop waiting for server to shut down.... done server stopped # No postmaster PID for node "standby1" ### Reloading node "publisher" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata reload server signaled ### Reloading node "publisher" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata reload server signaled [12:45:20.803](4.350s) ok 27 - subscriber1 doesn't get data as the sb1_slot doesn't catch up ### Reloading node "publisher" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata reload server signaled Waiting for replication conn regress_mysub1's replay_lsn to pass 0/6004F68 on publisher done [12:45:21.508](0.705s) ok 28 - subscriber1 gets data from primary after standby1 is removed from the standby_slot_names list ### Reloading node "publisher" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata reload server signaled ### Starting node "standby1" # Running: pg_ctl -w -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby1.log -o --cluster-name=standby1 start waiting for server to start.... done server started # Postmaster PID for node "standby1" is 8 Waiting for replication conn standby1's replay_lsn to pass 0/6004F68 on publisher done ### Promoting node "standby1" # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -l C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\log/040_standby_failover_slots_sync_standby1.log promote waiting for server to promote.... done server promoted [12:45:24.327](2.819s) ok 29 - last inactive time for slot lsub1_slot is valid on node standby1 [12:45:24.462](0.135s) ok 30 - synchronized slot has got its own inactive_since on the new primary after promotion [12:45:24.860](0.398s) ok 31 - synced slot retained on the new primary Waiting for replication conn regress_mysub1's replay_lsn to pass 0/6007398 on standby1 done [12:45:26.456](1.596s) ok 32 - data replicated from the new primary [12:45:26.561](0.105s) ok 33 - data can be consumed using snap_test_slot [12:45:26.561](0.000s) 1..33 ### Stopping node "publisher" using mode immediate # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_publisher_data/pgdata -m immediate stop waiting for server to shut down.... done server stopped # No postmaster PID for node "publisher" ### Stopping node "subscriber1" using mode immediate # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber1_data/pgdata -m immediate stop waiting for server to shut down.... done server stopped # No postmaster PID for node "subscriber1" ### Stopping node "standby1" using mode immediate # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby1_data/pgdata -m immediate stop waiting for server to shut down.... done server stopped # No postmaster PID for node "standby1" ### Stopping node "standby2" using mode immediate # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_standby2_data/pgdata -m immediate stop waiting for server to shut down.... done server stopped # No postmaster PID for node "standby2" ### Stopping node "subscriber2" using mode immediate # Running: pg_ctl -D C:\cirrus\build/testrun/recovery/040_standby_failover_slots_sync\data/t_040_standby_failover_slots_sync_subscriber2_data/pgdata -m immediate stop waiting for server to shut down.... done server stopped # No postmaster PID for node "subscriber2" [12:45:27.522](0.961s) # Looks like you failed 4 tests of 33.