(unnamed)

text/plain

Filename: (unnamed)
Type: text/plain
Part: 0
Message: Re: Race condition in recovery?
diff --git a/src/backend/access/transam/timeline.c b/src/backend/access/transam/timeline.c
index 8d0903c175..9483fd055c 100644
--- a/src/backend/access/transam/timeline.c
+++ b/src/backend/access/transam/timeline.c
@@ -55,6 +55,7 @@ restoreTimeLineHistoryFiles(TimeLineID begin, TimeLineID end)
 
 	for (tli = begin; tli < end; tli++)
 	{
+		elog(LOG, "Trying restoring history file for TLI=%d", tli);
 		if (tli == 1)
 			continue;
 
@@ -95,6 +96,7 @@ readTimeLineHistory(TimeLineID targetTLI)
 
 	if (ArchiveRecoveryRequested)
 	{
+		elog(LOG, "Trying reading history file for TLI=%d", targetTLI);
 		TLHistoryFileName(histfname, targetTLI);
 		fromArchive =
 			RestoreArchivedFile(path, histfname, "RECOVERYHISTORY", 0, false);
@@ -231,6 +233,7 @@ existsTimeLineHistory(TimeLineID probeTLI)
 
 	if (ArchiveRecoveryRequested)
 	{
+		elog(LOG, "Probing history file for TLI=%d", probeTLI);
 		TLHistoryFileName(histfname, probeTLI);
 		RestoreArchivedFile(path, histfname, "RECOVERYHISTORY", 0, false);
 	}
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 8d163f190f..afd6a0ce0a 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -3726,7 +3726,7 @@ XLogFileRead(XLogSegNo segno, int emode, TimeLineID tli,
 			snprintf(activitymsg, sizeof(activitymsg), "waiting for %s",
 					 xlogfname);
 			set_ps_display(activitymsg);
-
+			elog(LOG, "Trying fetching history file for TLI=%d", tli);
 			restoredFromArchive = RestoreArchivedFile(path, xlogfname,
 													  "RECOVERYXLOG",
 													  wal_segment_size,
@@ -3820,7 +3820,10 @@ XLogFileReadAnyTLI(XLogSegNo segno, int emode, XLogSource source)
 	if (expectedTLEs)
 		tles = expectedTLEs;
 	else
+	{
+		elog(LOG, "Loading history file for TLI=%d (2)", recoveryTargetTLI);
 		tles = readTimeLineHistory(recoveryTargetTLI);
+	}
 
 	foreach(cell, tles)
 	{
@@ -3834,6 +3837,8 @@ XLogFileReadAnyTLI(XLogSegNo segno, int emode, XLogSource source)
 		 * Skip scanning the timeline ID that the logfile segment to read
 		 * doesn't belong to
 		 */
+		elog(LOG, "scanning segment %lX TLI %d, source %d", segno, tli, source);
+
 		if (hent->begin != InvalidXLogRecPtr)
 		{
 			XLogSegNo	beginseg = 0;
@@ -3860,6 +3865,7 @@ XLogFileReadAnyTLI(XLogSegNo segno, int emode, XLogSource source)
 							  XLOG_FROM_ARCHIVE, true);
 			if (fd != -1)
 			{
+				elog(LOG, "found segment %lX TLI %d, from archive", segno, tli);
 				elog(DEBUG1, "got WAL segment from archive");
 				if (!expectedTLEs)
 					expectedTLEs = tles;
@@ -3873,6 +3879,7 @@ XLogFileReadAnyTLI(XLogSegNo segno, int emode, XLogSource source)
 							  XLOG_FROM_PG_WAL, true);
 			if (fd != -1)
 			{
+				elog(LOG, "found segment %lX TLI %d, from PG_WAL", segno, tli);
 				if (!expectedTLEs)
 					expectedTLEs = tles;
 				return fd;
@@ -6577,6 +6584,8 @@ StartupXLOG(void)
 	else
 		recoveryTargetTLI = ControlFile->checkPointCopy.ThisTimeLineID;
 
+	expectedTLEs = readTimeLineHistory(recoveryTargetTLI);
+	elog(LOG, "set expectedtles %d, %d", recoveryTargetTLI, list_length(expectedTLEs));
 	/*
 	 * Check for signal files, and if so set up state for offline recovery
 	 */
@@ -6866,11 +6875,19 @@ StartupXLOG(void)
 	if (!XLogRecPtrIsInvalid(ControlFile->minRecoveryPoint) &&
 		tliOfPointInHistory(ControlFile->minRecoveryPoint - 1, expectedTLEs) !=
 		ControlFile->minRecoveryPointTLI)
+	{
+		ListCell *lc;
+		foreach (lc, expectedTLEs)
+		{
+			TimeLineHistoryEntry *tle = (TimeLineHistoryEntry *) lfirst(lc);
+			elog(LOG, "TLE %d {%X/%X - %X/%X}", tle->tli, LSN_FORMAT_ARGS(tle->begin), LSN_FORMAT_ARGS(tle->end));
+		}
 		ereport(FATAL,
 				(errmsg("requested timeline %u does not contain minimum recovery point %X/%X on timeline %u",
 						recoveryTargetTLI,
 						LSN_FORMAT_ARGS(ControlFile->minRecoveryPoint),
 						ControlFile->minRecoveryPointTLI)));
+	}
 
 	LastRec = RecPtr = checkPointLoc;
 
@@ -8396,7 +8413,7 @@ ReadCheckpointRecord(XLogReaderState *xlogreader, XLogRecPtr RecPtr,
 
 	XLogBeginRead(xlogreader, RecPtr);
 	record = ReadRecord(xlogreader, LOG, true);
-
+	elog(LOG, "Checkpoint record: TLI=%d, %X/%X, rectargetTLI=%d, exptles=%p", xlogreader->seg.ws_tli, LSN_FORMAT_ARGS(xlogreader->ReadRecPtr), recoveryTargetTLI, expectedTLEs);
 	if (record == NULL)
 	{
 		if (!report)
@@ -10211,6 +10228,19 @@ xlog_redo(XLogReaderState *record)
 		CheckPoint	checkPoint;
 
 		memcpy(&checkPoint, XLogRecGetData(record), sizeof(CheckPoint));
+		{
+			struct stat b;
+			bool f = true;
+			while (stat("/tmp/hoge", &b) == 0)
+			{
+				if (f)
+					elog(LOG, "WAIT START: CHECKPOINT_ONLINE: TLI=%d", checkPoint.ThisTimeLineID);
+				f = false;
+				sleep(1);
+			}
+			if (!f)
+				elog(LOG, "WAIT END: CHECKPOINT_ONLINE");
+		}
 		/* In an ONLINE checkpoint, treat the XID counter as a minimum */
 		LWLockAcquire(XidGenLock, LW_EXCLUSIVE);
 		if (FullTransactionIdPrecedes(ShmemVariableCache->nextXid,
@@ -12595,7 +12625,7 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool randAccess,
 							 * TLI, rather than the position we're reading.
 							 */
 							tli = tliOfPointInHistory(tliRecPtr, expectedTLEs);
-
+							elog(LOG, "%X/%X is on TLI %X", LSN_FORMAT_ARGS(tliRecPtr), tli);
 							if (curFileTLI > 0 && tli < curFileTLI)
 								elog(ERROR, "according to history file, WAL location %X/%X belongs to timeline %u, but previous recovered WAL file came from timeline %u",
 									 LSN_FORMAT_ARGS(tliRecPtr),
@@ -12662,7 +12692,11 @@ WaitForWALToBecomeAvailable(XLogRecPtr RecPtr, bool randAccess,
 						if (readFile < 0)
 						{
 							if (!expectedTLEs)
-								expectedTLEs = readTimeLineHistory(receiveTLI);
+							{
+								
+								elog(LOG, "Loading expectedTLEs for %d (%d)", recoveryTargetTLI, receiveTLI);
+								expectedTLEs = readTimeLineHistory(recoveryTargetTLI);
+							}
 							readFile = XLogFileRead(readSegNo, PANIC,
 													receiveTLI,
 													XLOG_FROM_STREAM, false);