Try to improve readability of recovery/t/009_twophase.pl test.

The original coding here was very confusing, because it named the
two servers it set up "master" and "slave" even though it swapped
their replication roles multiple times.  At any given point in the
script it was very unobvious whether "$node_master" actually referred
to the server named "master" or the other one.  Instead, pick arbitrary
names for the two servers --- I used "london" and "paris" --- and
distinguish those permanent names from the nonce references $cur_master
and $cur_slave.  Add logging to help distinguish which is which at
any given point.  Also, use distinct data and transaction names to
make all the prepared transactions easily distinguishable in the
postmaster logs.  (There was one place where we intentionally tested
that the server could cope with re-use of a transaction name, but
it seems like one place is sufficient for that purpose.)

Also, add checks at the end to make sure that all the transactions
that were supposed to be committed did survive.

Discussion: https://postgr.es/m/28238.1499010855@sss.pgh.pa.us

diff --git a/src/test/recovery/t/009_twophase.pl b/src/test/recovery/t/009_twophase.pl
index 13b4a04205042d94c283c05acda27cb230c7ff98..93d0e974c4d515015d45adcccc70a29b2905a891 100644 (file)
--- a/src/test/recovery/t/009_twophase.pl
+++ b/src/test/recovery/t/009_twophase.pl
@@ -4,35 +4,45 @@ use warnings;
 
 use PostgresNode;
 use TestLib;
-use Test::More tests => 12;
+use Test::More tests => 17;
 
-# Setup master node
-my $node_master = get_new_node("master");
-$node_master->init(allows_streaming => 1);
-$node_master->append_conf(
+my $psql_out = '';
+my $psql_rc  = '';
+
+# Set up two nodes, which will alternately be master and replication slave.
+
+# Setup london node
+my $node_london = get_new_node("london");
+$node_london->init(allows_streaming => 1);
+$node_london->append_conf(
        'postgresql.conf', qq(
        max_prepared_transactions = 10
        log_checkpoints = true
 ));
-$node_master->start;
-$node_master->backup('master_backup');
-$node_master->psql('postgres', "CREATE TABLE t_009_tbl (id int)");
+$node_london->start;
+$node_london->backup('london_backup');
 
-# Setup slave node
-my $node_slave = get_new_node('slave');
-$node_slave->init_from_backup($node_master, 'master_backup',
+# Setup paris node
+my $node_paris = get_new_node('paris');
+$node_paris->init_from_backup($node_london, 'london_backup',
        has_streaming => 1);
-$node_slave->start;
+$node_paris->start;
 
 # Switch to synchronous replication
-$node_master->append_conf(
+$node_london->append_conf(
        'postgresql.conf', qq(
        synchronous_standby_names = '*'
 ));
-$node_master->psql('postgres', "SELECT pg_reload_conf()");
+$node_london->psql('postgres', "SELECT pg_reload_conf()",
+                  stdout => \$psql_out);
+is($psql_out, 't', 'Enable synchronous replication');
 
-my $psql_out = '';
-my $psql_rc  = '';
+note "Initially, london is master and paris is slave";
+my ($cur_master, $cur_slave) = ($node_london, $node_paris);
+my $cur_master_name = $cur_master->name;
+
+# Create table we'll use in the test transactions
+$cur_master->psql('postgres', "CREATE TABLE t_009_tbl (id int, msg text)");
 
 ###############################################################################
 # Check that we can commit and abort transaction after soft restart.
@@ -41,25 +51,25 @@ my $psql_rc  = '';
 # files.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (1, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
+       INSERT INTO t_009_tbl VALUES (2, 'issued to ${cur_master_name}');
        PREPARE TRANSACTION 'xact_009_1';
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (142);
+       INSERT INTO t_009_tbl VALUES (3, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (143);
+       INSERT INTO t_009_tbl VALUES (4, 'issued to ${cur_master_name}');
        PREPARE TRANSACTION 'xact_009_2';");
-$node_master->stop;
-$node_master->start;
+$cur_master->stop;
+$cur_master->start;
 
-$psql_rc = $node_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
+$psql_rc = $cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
 is($psql_rc, '0', 'Commit prepared transaction after restart');
 
-$psql_rc = $node_master->psql('postgres', "ROLLBACK PREPARED 'xact_009_2'");
+$psql_rc = $cur_master->psql('postgres', "ROLLBACK PREPARED 'xact_009_2'");
 is($psql_rc, '0', 'Rollback prepared transaction after restart');
 
 ###############################################################################
@@ -68,50 +78,50 @@ is($psql_rc, '0', 'Rollback prepared transaction after restart');
 # transaction using dedicated WAL records.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        CHECKPOINT;
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (5, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';
+       INSERT INTO t_009_tbl VALUES (6, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_3';
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (142);
+       INSERT INTO t_009_tbl VALUES (7, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (143);
-       PREPARE TRANSACTION 'xact_009_2';");
-$node_master->teardown_node;
-$node_master->start;
+       INSERT INTO t_009_tbl VALUES (8, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_4';");
+$cur_master->teardown_node;
+$cur_master->start;
 
-$psql_rc = $node_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
+$psql_rc = $cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_3'");
 is($psql_rc, '0', 'Commit prepared transaction after teardown');
 
-$psql_rc = $node_master->psql('postgres', "ROLLBACK PREPARED 'xact_009_2'");
+$psql_rc = $cur_master->psql('postgres', "ROLLBACK PREPARED 'xact_009_4'");
 is($psql_rc, '0', 'Rollback prepared transaction after teardown');
 
 ###############################################################################
 # Check that WAL replay can handle several transactions with same GID name.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        CHECKPOINT;
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (9, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';
-       COMMIT PREPARED 'xact_009_1';
+       INSERT INTO t_009_tbl VALUES (10, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_5';
+       COMMIT PREPARED 'xact_009_5';
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (11, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';");
-$node_master->teardown_node;
-$node_master->start;
+       INSERT INTO t_009_tbl VALUES (12, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_5';");
+$cur_master->teardown_node;
+$cur_master->start;
 
-$psql_rc = $node_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
+$psql_rc = $cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_5'");
 is($psql_rc, '0', 'Replay several transactions with same GID');
 
 ###############################################################################
@@ -119,42 +129,42 @@ is($psql_rc, '0', 'Replay several transactions with same GID');
 # while replaying transaction commits.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (13, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';
-       COMMIT PREPARED 'xact_009_1';");
-$node_master->teardown_node;
-$node_master->start;
-$psql_rc = $node_master->psql(
+       INSERT INTO t_009_tbl VALUES (14, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_6';
+       COMMIT PREPARED 'xact_009_6';");
+$cur_master->teardown_node;
+$cur_master->start;
+$psql_rc = $cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (15, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
+       INSERT INTO t_009_tbl VALUES (16, 'issued to ${cur_master_name}');
        -- This prepare can fail due to conflicting GID or locks conflicts if
        -- replay did not fully cleanup its state on previous commit.
-       PREPARE TRANSACTION 'xact_009_1';");
+       PREPARE TRANSACTION 'xact_009_7';");
 is($psql_rc, '0', "Cleanup of shared memory state for 2PC commit");
 
-$node_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
+$cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_7'");
 
 ###############################################################################
 # Check that WAL replay will cleanup its shared memory state on running slave.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (17, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';
-       COMMIT PREPARED 'xact_009_1';");
-$node_slave->psql(
+       INSERT INTO t_009_tbl VALUES (18, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_8';
+       COMMIT PREPARED 'xact_009_8';");
+$cur_slave->psql(
        'postgres',
        "SELECT count(*) FROM pg_prepared_xacts",
        stdout => \$psql_out);
@@ -166,16 +176,16 @@ is($psql_out, '0',
 # prepare and commit to use on-disk twophase files.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (19, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';");
-$node_slave->psql('postgres', "CHECKPOINT");
-$node_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
-$node_slave->psql(
+       INSERT INTO t_009_tbl VALUES (20, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_9';");
+$cur_slave->psql('postgres', "CHECKPOINT");
+$cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_9'");
+$cur_slave->psql(
        'postgres',
        "SELECT count(*) FROM pg_prepared_xacts",
        stdout => \$psql_out);
@@ -186,29 +196,33 @@ is($psql_out, '0',
 # Check that prepared transactions can be committed on promoted slave.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (21, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';");
-$node_master->teardown_node;
-$node_slave->promote;
-$node_slave->poll_query_until('postgres', "SELECT NOT pg_is_in_recovery()")
-  or die "Timed out while waiting for promotion of standby";
-
-$psql_rc = $node_slave->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
-is($psql_rc, '0', "Restore of prepared transaction on promoted slave");
+       INSERT INTO t_009_tbl VALUES (22, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_10';");
+$cur_master->teardown_node;
+$cur_slave->promote;
+$cur_slave->poll_query_until('postgres', "SELECT NOT pg_is_in_recovery()")
+  or die "Timed out while waiting for promotion of standby " . $cur_slave->name;
 
 # change roles
-($node_master, $node_slave) = ($node_slave, $node_master);
-$node_slave->enable_streaming($node_master);
-$node_slave->append_conf(
+note "Now paris is master and london is slave";
+($cur_master, $cur_slave) = ($node_paris, $node_london);
+$cur_master_name = $cur_master->name;
+
+$psql_rc = $cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_10'");
+is($psql_rc, '0', "Restore of prepared transaction on promoted slave");
+
+# restart old master as new slave
+$cur_slave->enable_streaming($cur_master);
+$cur_slave->append_conf(
        'recovery.conf', qq(
 recovery_target_timeline='latest'
 ));
-$node_slave->start;
+$cur_slave->start;
 
 ###############################################################################
 # Check that prepared transactions are replayed after soft restart of standby
@@ -217,93 +231,176 @@ $node_slave->start;
 # consistent.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (42);
+       INSERT INTO t_009_tbl VALUES (23, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (43);
-       PREPARE TRANSACTION 'xact_009_1';");
-$node_master->stop;
-$node_slave->restart;
-$node_slave->promote;
-$node_slave->poll_query_until('postgres', "SELECT NOT pg_is_in_recovery()")
-  or die "Timed out while waiting for promotion of standby";
-
-$node_slave->psql(
+       INSERT INTO t_009_tbl VALUES (24, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_11';");
+$cur_master->stop;
+$cur_slave->restart;
+$cur_slave->promote;
+$cur_slave->poll_query_until('postgres', "SELECT NOT pg_is_in_recovery()")
+  or die "Timed out while waiting for promotion of standby " . $cur_slave->name;
+
+# change roles
+note "Now london is master and paris is slave";
+($cur_master, $cur_slave) = ($node_london, $node_paris);
+$cur_master_name = $cur_master->name;
+
+$cur_master->psql(
        'postgres',
        "SELECT count(*) FROM pg_prepared_xacts",
        stdout => \$psql_out);
 is($psql_out, '1',
        "Restore prepared transactions from files with master down");
 
-# restore state
-($node_master, $node_slave) = ($node_slave, $node_master);
-$node_slave->enable_streaming($node_master);
-$node_slave->append_conf(
+# restart old master as new slave
+$cur_slave->enable_streaming($cur_master);
+$cur_slave->append_conf(
        'recovery.conf', qq(
 recovery_target_timeline='latest'
 ));
-$node_slave->start;
-$node_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
+$cur_slave->start;
+
+$cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_11'");
 
 ###############################################################################
 # Check that prepared transactions are correctly replayed after slave hard
 # restart while master is down.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       INSERT INTO t_009_tbl VALUES (242);
+       INSERT INTO t_009_tbl VALUES (25, 'issued to ${cur_master_name}');
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl VALUES (243);
-       PREPARE TRANSACTION 'xact_009_1';
+       INSERT INTO t_009_tbl VALUES (26, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_12';
        ");
-$node_master->stop;
-$node_slave->teardown_node;
-$node_slave->start;
-$node_slave->promote;
-$node_slave->poll_query_until('postgres', "SELECT NOT pg_is_in_recovery()")
-  or die "Timed out while waiting for promotion of standby";
-
-$node_slave->psql(
+$cur_master->stop;
+$cur_slave->teardown_node;
+$cur_slave->start;
+$cur_slave->promote;
+$cur_slave->poll_query_until('postgres', "SELECT NOT pg_is_in_recovery()")
+  or die "Timed out while waiting for promotion of standby " . $cur_slave->name;
+
+# change roles
+note "Now paris is master and london is slave";
+($cur_master, $cur_slave) = ($node_paris, $node_london);
+$cur_master_name = $cur_master->name;
+
+$cur_master->psql(
        'postgres',
        "SELECT count(*) FROM pg_prepared_xacts",
        stdout => \$psql_out);
 is($psql_out, '1',
        "Restore prepared transactions from records with master down");
 
-# restore state
-($node_master, $node_slave) = ($node_slave, $node_master);
-$node_slave->enable_streaming($node_master);
-$node_slave->append_conf(
+# restart old master as new slave
+$cur_slave->enable_streaming($cur_master);
+$cur_slave->append_conf(
        'recovery.conf', qq(
 recovery_target_timeline='latest'
 ));
-$node_slave->start;
-$node_master->psql('postgres', "COMMIT PREPARED 'xact_009_1'");
+$cur_slave->start;
 
+$cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_12'");
 
 ###############################################################################
 # Check for a lock conflict between prepared transaction with DDL inside and replay of
 # XLOG_STANDBY_LOCK wal record.
 ###############################################################################
 
-$node_master->psql(
+$cur_master->psql(
        'postgres', "
        BEGIN;
-       CREATE TABLE t_009_tbl2 (id int);
+       CREATE TABLE t_009_tbl2 (id int, msg text);
        SAVEPOINT s1;
-       INSERT INTO t_009_tbl2 VALUES (42);
-       PREPARE TRANSACTION 'xact_009_1';
+       INSERT INTO t_009_tbl2 VALUES (27, 'issued to ${cur_master_name}');
+       PREPARE TRANSACTION 'xact_009_13';
        -- checkpoint will issue XLOG_STANDBY_LOCK that can conflict with lock
        -- held by 'create table' statement
        CHECKPOINT;
-       COMMIT PREPARED 'xact_009_1';");
+       COMMIT PREPARED 'xact_009_13';");
 
-$node_slave->psql(
+$cur_slave->psql(
        'postgres',
        "SELECT count(*) FROM pg_prepared_xacts",
        stdout => \$psql_out);
 is($psql_out, '0', "Replay prepared transaction with DDL");
+
+###############################################################################
+# Verify expected data appears on both servers.
+###############################################################################
+
+$cur_master->psql(
+       'postgres',
+       "SELECT * FROM t_009_tbl ORDER BY id",
+       stdout => \$psql_out);
+is($psql_out, qq{1|issued to london
+2|issued to london
+5|issued to london
+6|issued to london
+9|issued to london
+10|issued to london
+11|issued to london
+12|issued to london
+13|issued to london
+14|issued to london
+15|issued to london
+16|issued to london
+17|issued to london
+18|issued to london
+19|issued to london
+20|issued to london
+21|issued to london
+22|issued to london
+23|issued to paris
+24|issued to paris
+25|issued to london
+26|issued to london},
+   "Check expected t_009_tbl data on master");
+
+$cur_master->psql(
+       'postgres',
+       "SELECT * FROM t_009_tbl2",
+       stdout => \$psql_out);
+is($psql_out, qq{27|issued to paris},
+   "Check expected t_009_tbl2 data on master");
+
+$cur_slave->psql(
+       'postgres',
+       "SELECT * FROM t_009_tbl ORDER BY id",
+       stdout => \$psql_out);
+is($psql_out, qq{1|issued to london
+2|issued to london
+5|issued to london
+6|issued to london
+9|issued to london
+10|issued to london
+11|issued to london
+12|issued to london
+13|issued to london
+14|issued to london
+15|issued to london
+16|issued to london
+17|issued to london
+18|issued to london
+19|issued to london
+20|issued to london
+21|issued to london
+22|issued to london
+23|issued to paris
+24|issued to paris
+25|issued to london
+26|issued to london},
+   "Check expected t_009_tbl data on slave");
+
+$cur_slave->psql(
+       'postgres',
+       "SELECT * FROM t_009_tbl2",
+       stdout => \$psql_out);
+is($psql_out, qq{27|issued to paris},
+   "Check expected t_009_tbl2 data on slave");