From e1cc6cad91752bb7e71bb640f123684a5891ae55 Mon Sep 17 00:00:00 2001
From: Peter Smith <peter.b.smith@fujitsu.com>
Date: Mon, 25 Jan 2021 13:25:07 +1100
Subject: [PATCH v19] 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     | 20 +++++++++++++++++--
 src/backend/replication/logical/tablesync.c | 30 +++++++++++++++++++++++++++--
 2 files changed, 46 insertions(+), 4 deletions(-)

diff --git a/src/backend/commands/subscriptioncmds.c b/src/backend/commands/subscriptioncmds.c
index af13448..ef0817c 100644
--- a/src/backend/commands/subscriptioncmds.c
+++ b/src/backend/commands/subscriptioncmds.c
@@ -660,10 +660,18 @@ AlterSubscription_refresh(Subscription *sub, bool copy_data)
 			snprintf(originname, sizeof(originname), "pg_%u_%u", sub->oid, relid);
 			originid = replorigin_by_name(originname, true);
 			if (originid != InvalidRepOriginId)
+			{
+				elog(LOG,
+					 "!!>> AlterSubscription_refresh: dropping origin tracking for \"%s\"",
+					 originname);
 				replorigin_drop(originid, false /* nowait */ );
+				elog(LOG,
+					 "!!>> AlterSubscription_refresh: dropped origin tracking for \"%s\"",
+					 originname);
+			}
 
-			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)));
@@ -1071,7 +1079,15 @@ DropSubscription(DropSubscriptionStmt *stmt, bool isTopLevel)
 		snprintf(originname, sizeof(originname), "pg_%u_%u", subid, relid);
 		originid = replorigin_by_name(originname, true);
 		if (originid != InvalidRepOriginId)
+		{
+			elog(LOG,
+				 "!!>> DropSubscription: dropping origin tracking for \"%s\"",
+				 originname);
 			replorigin_drop(originid, false /* nowait */ );
+			elog(LOG,
+				 "!!>> DropSubscription: droppped origin tracking for \"%s\"",
+				 originname);
+		}
 	}
 	list_free(rstates);
 
diff --git a/src/backend/replication/logical/tablesync.c b/src/backend/replication/logical/tablesync.c
index ae446f5..3693f4c 100644
--- a/src/backend/replication/logical/tablesync.c
+++ b/src/backend/replication/logical/tablesync.c
@@ -444,10 +444,13 @@ process_syncing_tables_for_apply(XLogRecPtr current_lsn)
 				originid = replorigin_by_name(originname, true);
 				if (OidIsValid(originid))
 				{
-					elog(DEBUG1,
-						 "process_syncing_tables_for_apply: dropping tablesync origin tracking for \"%s\".",
+					elog(LOG,
+						 "!!>> process_syncing_tables_for_apply: dropping tablesync origin tracking for \"%s\".",
 						 originname);
 					replorigin_drop(originid, false /* nowait */ );
+					elog(LOG,
+						 "!!>> process_syncing_tables_for_apply: dropped tablesync origin tracking for \"%s\".",
+						 originname);
 				}
 
 				/*
@@ -929,12 +932,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 */ );
 
@@ -943,8 +951,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;
@@ -993,6 +1007,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);
 
@@ -1024,13 +1041,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