From 878e4ed4fdb8e4b67c1f98bc4dd22c4f95654a5e Mon Sep 17 00:00:00 2001
From: Peter Smith <peter.b.smith@fujitsu.com>
Date: Mon, 25 Jan 2021 21:36:46 +1100
Subject: [PATCH v20] Tablesync extra logging.

This patch only adds some extra logging which may be helpful for testing, but is not for committing.
---
 src/backend/commands/subscriptioncmds.c     |  6 ++++--
 src/backend/replication/logical/tablesync.c | 31 +++++++++++++++++++++++++++++
 2 files changed, 35 insertions(+), 2 deletions(-)

diff --git a/src/backend/commands/subscriptioncmds.c b/src/backend/commands/subscriptioncmds.c
index 676da19..154a2da 100644
--- a/src/backend/commands/subscriptioncmds.c
+++ b/src/backend/commands/subscriptioncmds.c
@@ -654,10 +654,11 @@ AlterSubscription_refresh(Subscription *sub, bool copy_data)
 			logicalrep_worker_stop_at_commit(sub->oid, relid);
 
 			/* Remove the tablesync's origin tracking if exists. */
+			elog(LOG, "!!>> AlterSubscription_refresh: tablesync_replorigin_drop");
 			tablesync_replorigin_drop(sub->oid, relid, false /* nowait */ );
 
-			ereport(DEBUG1,
-					(errmsg("table \"%s.%s\" removed from subscription \"%s\"",
+			ereport(LOG,
+					(errmsg("!!>> table \"%s.%s\" removed from subscription \"%s\"",
 							get_namespace_name(get_rel_namespace(relid)),
 							get_rel_name(relid),
 							sub->name)));
@@ -1062,6 +1063,7 @@ DropSubscription(DropSubscriptionStmt *stmt, bool isTopLevel)
 			continue;
 
 		/* Remove the tablesync's origin tracking if exists. */
+		elog(LOG, "!!>> DropSubscription: tablesync_replorigin_drop");
 		tablesync_replorigin_drop(subid, relid, false /* nowait */ );
 	}
 	list_free(rstates);
diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index 5870334..a3db3e5 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -143,7 +143,13 @@ tablesync_replorigin_drop(Oid subid, Oid relid, bool nowait)
 	{
 		PG_TRY();
 		{
+			elog(LOG,
+				 "!!>> tablesync_replorigin_drop: dropping origin \"%s\"",
+				 originname);
 			replorigin_drop(originid, nowait);
+			elog(LOG,
+				 "!!>> tablesync_replorigin_drop: dropped origin \"%s\"",
+				 originname);
 		}
 		PG_CATCH();
 		{
@@ -474,6 +480,8 @@ process_syncing_tables_for_apply(XLogRecPtr current_lsn)
 				 * tablesync worker process attempted to drop its own origin
 				 * then it would fail (origin is "busy").
 				 */
+				elog(LOG,
+					 "!!>> process_syncing_tables_for_apply: tablesync_replorigin_drop");
 				tablesync_replorigin_drop(MyLogicalRepWorker->subid,
 										  rstate->relid, false /* nowait */ );
 
@@ -956,12 +964,17 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos)
 		 * The COPY phase was previously done, but tablesync then crashed
 		 * before it was able to finish normally.
 		 */
+		elog(LOG,
+			 "!!>> LogicalRepSyncTableStart: tablesync relstate was SUBREL_STATE_FINISHEDCOPY.");
 		StartTransactionCommand();
 
 		/*
 		 * Slot creation passes NULL lsn because the origin startpos is got
 		 * from origin tracking this time, not from the slot.
 		 */
+		elog(LOG,
+			 "!!>> LogicalRepSyncTableStart: 2 walrcv_create_slot for \"%s\".",
+			 slotname);
 		walrcv_create_slot(wrconn, slotname, true /* temporary */ ,
 						   CRS_NOEXPORT_SNAPSHOT, NULL /* lsn */ );
 
@@ -970,8 +983,14 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos)
 		 * time this tablesync was launched.
 		 */
 		originid = replorigin_by_name(originname, false /* missing_ok */ );
+		elog(LOG,
+			 "!!>> LogicalRepSyncTableStart: 2 replorigin_session_setup \"%s\".",
+			 originname);
 		replorigin_session_setup(originid);
 		replorigin_session_origin = originid;
+		elog(LOG,
+			 "!!>> LogicalRepSyncTableStart: 2 replorigin_session_get_progress \"%s\".",
+			 originname);
 		*origin_startpos = replorigin_session_get_progress(false);
 
 		goto copy_table_done;
@@ -1020,6 +1039,9 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos)
 	 * for the catchup phase after COPY is done, so tell it to use the
 	 * snapshot to make the final data consistent.
 	 */
+	elog(LOG,
+		 "!!>> LogicalRepSyncTableStart: 1 walrcv_create_slot for \"%s\".",
+		 slotname);
 	walrcv_create_slot(wrconn, slotname, true,
 					   CRS_USE_SNAPSHOT, origin_startpos);
 
@@ -1051,13 +1073,22 @@ LogicalRepSyncTableStart(XLogRecPtr *origin_startpos)
 		 * logged for the purpose of recovery. Locks are to prevent the
 		 * replication origin from vanishing while advancing.
 		 */
+		elog(LOG,
+			 "!!>> LogicalRepSyncTableStart: 1 replorigin_create \"%s\".",
+			 originname);
 		originid = replorigin_create(originname);
 
 		LockRelationOid(ReplicationOriginRelationId, RowExclusiveLock);
+		elog(LOG,
+			 "!!>> LogicalRepSyncTableStart: 1 replorigin_advance \"%s\".",
+			 originname);
 		replorigin_advance(originid, *origin_startpos, InvalidXLogRecPtr,
 						   true /* go backward */ , true /* WAL log */ );
 		UnlockRelationOid(ReplicationOriginRelationId, RowExclusiveLock);
 
+		elog(LOG,
+			 "!!>> LogicalRepSyncTableStart: 1 replorigin_session_setup \"%s\".",
+			 originname);
 		replorigin_session_setup(originid);
 		replorigin_session_origin = originid;
 	}
-- 
1.8.3.1