Test failures of 100_bugs.pl

From 2cf7b69211b597e27b67599ea62e3a3fee70f4b6 Mon Sep 17 00:00:00 2001
From: Shi Yu <shiy.fnst@fujitsu.com>
Date: Thu, 20 Apr 2023 10:47:09 +0800
Subject: [PATCH v1] dump rel state in wait_for_subscription_sync

---
 src/test/perl/PostgreSQL/Test/Cluster.pm | 20 ++++++++++++++++++--
 1 file changed, 18 insertions(+), 2 deletions(-)

diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index 6f7f4e5de4..8130a8ac4a 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -2774,8 +2774,24 @@ sub wait_for_subscription_sync
 	print "Waiting for all subscriptions in \"$name\" to synchronize data\n";
 	my $query =
 	    qq[SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');];
-	$self->poll_query_until($dbname, $query)
-	  or croak "timed out waiting for subscriber to synchronize data";
+	if (!$self->poll_query_until($dbname, $query))
+	{
+		my $result = $self->safe_psql(
+			$dbname, qq(
+			SELECT
+				PS.subname AS subname,
+				N.nspname AS schemaname,
+				C.relname AS relname,
+				PSR.srsubstate AS substate
+			FROM pg_subscription_rel AS PSR
+				JOIN pg_subscription PS ON (PS.oid = PSR.srsubid)
+				JOIN pg_class C ON (C.oid = PSR.srrelid)
+				JOIN pg_namespace N ON (N.oid = C.relnamespace);
+		));
+		print "### Subscription rel state\n";
+		print "$result\n";
+		croak "timed out waiting for subscriber to synchronize data";
+	}
 
 	# Then, wait for the replication to catchup if required.
 	if (defined($publisher))
-- 
2.31.1

From fc083fa6320605c54ae0d7b11ce5102c13977491 Mon Sep 17 00:00:00 2001
From: Shi Yu <shiy.fnst@fujitsu.com>
Date: Mon, 24 Apr 2023 17:25:56 +0800
Subject: [PATCH v2 1/2] dump rel state in wait_for_subscription_sync

---
 src/test/perl/PostgreSQL/Test/Cluster.pm | 21 +++++++++++++++++++--
 1 file changed, 19 insertions(+), 2 deletions(-)

diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm
index 6f7f4e5de4..89cfc0f8a0 100644
--- a/src/test/perl/PostgreSQL/Test/Cluster.pm
+++ b/src/test/perl/PostgreSQL/Test/Cluster.pm
@@ -2774,8 +2774,25 @@ sub wait_for_subscription_sync
 	print "Waiting for all subscriptions in \"$name\" to synchronize data\n";
 	my $query =
 	    qq[SELECT count(1) = 0 FROM pg_subscription_rel WHERE srsubstate NOT IN ('r', 's');];
-	$self->poll_query_until($dbname, $query)
-	  or croak "timed out waiting for subscriber to synchronize data";
+	if (!$self->poll_query_until($dbname, $query))
+	{
+		my $result = $self->safe_psql(
+			$dbname, qq(
+			SELECT
+				PS.subname,
+				N.nspname,
+				C.relname,
+				PSR.srrelid,
+				PSR.srsubstate
+			FROM pg_subscription_rel AS PSR
+				JOIN pg_subscription PS ON (PS.oid = PSR.srsubid)
+				JOIN pg_class C ON (C.oid = PSR.srrelid)
+				JOIN pg_namespace N ON (N.oid = C.relnamespace);
+		));
+		print "### Subscription rel state\n";
+		print "$result\n";
+		croak "timed out waiting for subscriber to synchronize data";
+	}
 
 	# Then, wait for the replication to catchup if required.
 	if (defined($publisher))
-- 
2.30.0.windows.2

From 0359554d9e1fa808991b72757b1f11cfbcc96075 Mon Sep 17 00:00:00 2001
From: Shi Yu <shiy.fnst@fujitsu.com>
Date: Mon, 24 Apr 2023 17:26:36 +0800
Subject: [PATCH v2 2/2] Add logs to help investigate subscription test failure

---
 src/backend/replication/logical/tablesync.c | 3 +++
 src/test/subscription/t/014_binary.pl       | 8 ++++++++
 src/test/subscription/t/100_bugs.pl         | 9 +++++++++
 3 files changed, 20 insertions(+)

diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index 0c71ae9ba7..82f7474d5f 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -272,6 +272,7 @@ void
 invalidate_syncing_table_states(Datum arg, int cacheid, uint32 hashvalue)
 {
 	table_states_valid = false;
+	elog(DEBUG1, "invalidating syncing table states");
 }
 
 /*
@@ -1549,6 +1550,8 @@ FetchTableStates(bool *started_tx)
 			rstate = palloc(sizeof(SubscriptionRelState));
 			memcpy(rstate, lfirst(lc), sizeof(SubscriptionRelState));
 			table_states_not_ready = lappend(table_states_not_ready, rstate);
+			elog(DEBUG1, "not ready subscription table %u, state: %c",
+				 rstate->relid, rstate->state);
 		}
 		MemoryContextSwitchTo(oldctx);
 
diff --git a/src/test/subscription/t/014_binary.pl b/src/test/subscription/t/014_binary.pl
index feefbe734e..e012b9ed3a 100644
--- a/src/test/subscription/t/014_binary.pl
+++ b/src/test/subscription/t/014_binary.pl
@@ -257,6 +257,10 @@ $node_publisher->safe_psql(
 # Check the subscriber log from now on.
 $offset = -s $node_subscriber->logfile;
 
+# Adjust log_min_messages, this helps when the test fails.
+$node_subscriber->append_conf('postgresql.conf', "log_min_messages = debug1");
+$node_subscriber->reload;
+
 $node_subscriber->safe_psql(
 	'postgres', qq(
     CREATE TABLE public.test_mismatching_types (
@@ -283,6 +287,10 @@ $node_publisher->wait_for_log(
 
 $node_subscriber->wait_for_subscription_sync($node_publisher, 'tsub');
 
+# Reset the log_min_messages to default.
+$node_subscriber->append_conf('postgresql.conf', "log_min_messages = warning");
+$node_subscriber->reload;
+
 # Check the synced data on the subscriber
 $result = $node_subscriber->safe_psql('postgres',
 	'SELECT a FROM test_mismatching_types ORDER BY a;');
diff --git a/src/test/subscription/t/100_bugs.pl b/src/test/subscription/t/100_bugs.pl
index b832ddcf63..78cf555a9a 100644
--- a/src/test/subscription/t/100_bugs.pl
+++ b/src/test/subscription/t/100_bugs.pl
@@ -151,6 +151,11 @@ $node_twoways->safe_psql(
 	INSERT INTO t2 SELECT * FROM generate_series(1, $rows);
 	});
 $node_twoways->safe_psql('d1', 'ALTER PUBLICATION testpub ADD TABLE t2');
+
+# Adjust log_min_messages, this helps when the test fails.
+$node_twoways->append_conf('postgresql.conf', "log_min_messages = debug1");
+$node_twoways->reload;
+
 $node_twoways->safe_psql('d2',
 	'ALTER SUBSCRIPTION testsub REFRESH PUBLICATION');
 
@@ -159,6 +164,10 @@ $node_twoways->safe_psql('d2',
 # verify that tables are synced.
 $node_twoways->wait_for_subscription_sync($node_twoways, 'testsub', 'd2');
 
+# Reset the log_min_messages to default.
+$node_twoways->append_conf('postgresql.conf', "log_min_messages = warning");
+$node_twoways->reload;
+
 is($node_twoways->safe_psql('d2', "SELECT count(f) FROM t"),
 	$rows * 2, "2x$rows rows in t");
 is($node_twoways->safe_psql('d2', "SELECT count(f) FROM t2"),
-- 
2.30.0.windows.2