[bug fix] Cascading standby cannot catch up and get stuck emitting the same message repeatedly
Hello,
Our customer hit a problem of cascading replication, and we found the cause. They are using the latest PostgreSQL 9.2.18. The bug seems to have been fixed in 9.4 and higher during the big modification of xlog.c, but it's not reflected in older releases.
The attached patch is for 9.2.18. This just borrows the idea from 9.4 and higher.
But we haven't been able to reproduce the problem. Could you review the patch and help to test it? I would very much appreciate it if you could figure out how to reproduce the problem easily.
PROBLEM
========================================
The customer's configuration consists of three nodes: node1 is a primary, node2 is a synchronous standby, and node3 is a cascading standby. The primary archives WAL to a shared (network?) storage and the standbys read archived WAL from there with restore_command. recovery_target_timeline is set to 'latest' on the standbys.
When node1 dies and node2 is promoted to a primary, node3 cannot catch up node2 forever, emitting the following message repeatedly:
LOG: out-of-sequence timeline ID 140 (after 141) in log file 652, segment 117, offset 0
The expected behavior is that node3 catches up node2 and keeps synchronization.
CAUSE
========================================
The processing went as follows.
1. node1's timeline is 140. It wrote a WAL record at the end of WAL segment 117. The WAL record didn't fit the last page, so it was split across segments 117 and 118.
2. WAL segment 117 was archived.
3. node1 got down, and node2 was promoted.
4. As part of the recovery process, node2 retrieves WAL segment 117 from archive. It found a WAL record fragment at the end of the segment but could not find the remaining fragment in segment 118, so node2 stops recovery there.
LOG: restored log file "0000008C0000028C00000075" from archive
LOG: received promote request
LOG: redo done at 28C/75FFF738
5. node2 becomes the primary, and its timeline becomes 118. node3 is disconnected by node2 (but later reconnectes to node2).
LOG: terminating all walsender processes to force cascaded standby(s) to update timeline and reconnect
6. node3 retrieves and applies WAL segment 117 from archive.
LOG: restored log file "0000008C0000028C00000075" from archive
7. node3 found .history file for time line 141 and renews its timeline to 141.
8. Because node3 found a WAL record fragment at the end of segment 117, it expects to find the remaining fragment at the beginning of WAL segment 118 streamed from node2. But there was a fragment of a different WAL record, because node2 overwrote a different WAL record at the end of segment 117 across to 118.
LOG: invalid contrecord length 5892 in log file 652, segment 118, offset 0
9. node3 then retrieves segment 117 from archive again to get the WAL record at the end of segment 117. However, as node3's timeline is already 141, it complains about the older timeline when it sees the timeline 140 at the beginning of segment 117.
LOG: out-of-sequence timeline ID 140 (after 141) in log file 652, segment 117, offset 0
Regards
Takayuki Tsunakawa
Attachments:
cascading_standby_stuck.patchapplication/octet-stream; name=cascading_standby_stuck.patchDownload
diff -Nacr a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
*** a/src/backend/access/transam/xlog.c 2016-08-09 05:33:27.000000000 +0900
--- b/src/backend/access/transam/xlog.c 2016-08-26 10:27:55.000000000 +0900
***************
*** 589,596 ****
/* State information for XLOG reading */
static XLogRecPtr ReadRecPtr; /* start of last record read */
static XLogRecPtr EndRecPtr; /* end+1 of last record read */
! static TimeLineID lastPageTLI = 0;
! static TimeLineID lastSegmentTLI = 0;
static XLogRecPtr minRecoveryPoint; /* local copy of
* ControlFile->minRecoveryPoint */
--- 589,596 ----
/* State information for XLOG reading */
static XLogRecPtr ReadRecPtr; /* start of last record read */
static XLogRecPtr EndRecPtr; /* end+1 of last record read */
! static XLogRecPtr latestPagePtr; /* start of last page read */
! static TimeLineID latestPageTLI = 0;
static XLogRecPtr minRecoveryPoint; /* local copy of
* ControlFile->minRecoveryPoint */
***************
*** 678,684 ****
static void UpdateMinRecoveryPoint(XLogRecPtr lsn, bool force);
static XLogRecord *ReadRecord(XLogRecPtr *RecPtr, int emode, bool fetching_ckpt);
static void CheckRecoveryConsistency(void);
! static bool ValidXLOGHeader(XLogPageHeader hdr, int emode, bool segmentonly);
static XLogRecord *ReadCheckpointRecord(XLogRecPtr RecPtr, int whichChkpt);
static List *readTimeLineHistory(TimeLineID targetTLI);
static bool existsTimeLineHistory(TimeLineID probeTLI);
--- 678,684 ----
static void UpdateMinRecoveryPoint(XLogRecPtr lsn, bool force);
static XLogRecord *ReadRecord(XLogRecPtr *RecPtr, int emode, bool fetching_ckpt);
static void CheckRecoveryConsistency(void);
! static bool ValidXLOGHeader(XLogPageHeader hdr, int emode);
static XLogRecord *ReadCheckpointRecord(XLogRecPtr RecPtr, int whichChkpt);
static List *readTimeLineHistory(TimeLineID targetTLI);
static bool existsTimeLineHistory(TimeLineID probeTLI);
***************
*** 3992,4005 ****
(errmsg("invalid record offset at %X/%X",
RecPtr->xlogid, RecPtr->xrecoff)));
- /*
- * Since we are going to a random position in WAL, forget any prior
- * state about what timeline we were in, and allow it to be any
- * timeline in expectedTLIs. We also set a flag to allow curFileTLI
- * to go backwards (but we can't reset that variable right here, since
- * we might not change files at all).
- */
- lastPageTLI = lastSegmentTLI = 0; /* see comment in ValidXLOGHeader */
randAccess = true; /* allow curFileTLI to go backwards too */
}
--- 3992,3997 ----
***************
*** 4317,4323 ****
* ReadRecord. It's not intended for use from anywhere else.
*/
static bool
! ValidXLOGHeader(XLogPageHeader hdr, int emode, bool segmentonly)
{
XLogRecPtr recaddr;
--- 4309,4315 ----
* ReadRecord. It's not intended for use from anywhere else.
*/
static bool
! ValidXLOGHeader(XLogPageHeader hdr, int emode)
{
XLogRecPtr recaddr;
***************
*** 4411,4441 ****
* immediate parent's TLI, we should never see TLI go backwards across
* successive pages of a consistent WAL sequence.
*
! * Of course this check should only be applied when advancing sequentially
! * across pages; therefore ReadRecord resets lastPageTLI and
! * lastSegmentTLI to zero when going to a random page.
! *
! * Sometimes we re-open a segment that's already been partially replayed.
! * In that case we cannot perform the normal TLI check: if there is a
! * timeline switch within the segment, the first page has a smaller TLI
! * than later pages following the timeline switch, and we might've read
! * them already. As a weaker test, we still check that it's not smaller
! * than the TLI we last saw at the beginning of a segment. Pass
! * segmentonly = true when re-validating the first page like that, and the
! * page you're actually interested in comes later.
*/
! if (hdr->xlp_tli < (segmentonly ? lastSegmentTLI : lastPageTLI))
{
! ereport(emode_for_corrupt_record(emode, recaddr),
! (errmsg("out-of-sequence timeline ID %u (after %u) in log file %u, segment %u, offset %u",
! hdr->xlp_tli,
! segmentonly ? lastSegmentTLI : lastPageTLI,
! readId, readSeg, readOff)));
! return false;
}
! lastPageTLI = hdr->xlp_tli;
! if (readOff == 0)
! lastSegmentTLI = hdr->xlp_tli;
return true;
}
--- 4403,4426 ----
* immediate parent's TLI, we should never see TLI go backwards across
* successive pages of a consistent WAL sequence.
*
! * Sometimes we re-read a segment that's already been (partially) read. So
! * we only verify TLIs for pages that are later than the last remembered
! * LSN.
*/
! if (XLByteLT(latestPagePtr, recaddr))
{
! if (hdr->xlp_tli < latestPageTLI)
! {
! ereport(emode_for_corrupt_record(emode, recaddr),
! (errmsg("out-of-sequence timeline ID %u (after %u) in log file %u, segment %u, offset %u",
! hdr->xlp_tli,
! latestPageTLI,
! readId, readSeg, readOff)));
! return false;
! }
}
! latestPagePtr = recaddr;
! latestPageTLI = hdr->xlp_tli;
return true;
}
***************
*** 10803,10809 ****
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode, true))
goto next_record_is_invalid;
}
--- 10788,10794 ----
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode))
goto next_record_is_invalid;
}
***************
*** 10825,10831 ****
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode, false))
goto next_record_is_invalid;
Assert(targetId == readId);
--- 10810,10816 ----
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode))
goto next_record_is_invalid;
Assert(targetId == readId);
On Fri, Aug 26, 2016 at 11:33 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
Our customer hit a problem of cascading replication, and we found the cause. They are using the latest PostgreSQL 9.2.18. The bug seems to have been fixed in 9.4 and higher during the big modification of xlog.c, but it's not reflected in older releases.
The attached patch is for 9.2.18. This just borrows the idea from 9.4 and higher.
But we haven't been able to reproduce the problem. Could you review the patch and help to test it? I would very much appreciate it if you could figure out how to reproduce the problem easily.
[...]
LOG: out-of-sequence timeline ID 140 (after 141) in log file 652, segment 117, offset 0
9.3 has addressed that by allowing streaming standbys to perform
timeline jumps via the replication protocol. Doesn't this problem
enter in this area?
--
Michael
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Michael Paquier
9.3 has addressed that by allowing streaming standbys to perform timeline
jumps via the replication protocol. Doesn't this problem enter in this area?
IIUC, that new feature enables timeline switch without disconnecting the standby and without WAL archive. I think 9.2 can perform timeline switch with WAL archive. In fact, the customer said they hit the problem only once in many occurrences of the same test. The bug seems to emerge depending on the timing.
Regards
Takayuki Tsunakawa
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Tsunakawa,
Our customer hit a problem of cascading replication, and we found the cause.
They are using the latest PostgreSQL 9.2.18. The bug seems to have been
fixed in 9.4 and higher during the big modification of xlog.c, but it's
not reflected in older releases.The attached patch is for 9.2.18. This just borrows the idea from 9.4 and
higher.But we haven't been able to reproduce the problem. Could you review the
patch and help to test it? I would very much appreciate it if you could
figure out how to reproduce the problem easily.
We could successfully reproduce the problem and confirm that the patch fixes it. Please use the attached script to reproduce the problem. Place it in an empty directory and just run "./test.sh" with no argument. It creates three database clusters (primary, standby, and cascading standby) in the current directory.
Could you review the patch and commit it for the next release? If you think I should register the patch with the CommitFest even if the problem occurs in 9.2 and 9.3, please say so. I'll do so if there's no comment.
Regards
Takayuki Tsunakawa
Attachments:
On Thu, Aug 25, 2016 at 10:33 PM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
The processing went as follows.
1. node1's timeline is 140. It wrote a WAL record at the end of WAL segment 117. The WAL record didn't fit the last page, so it was split across segments 117 and 118.
2. WAL segment 117 was archived.
3. node1 got down, and node2 was promoted.
4. As part of the recovery process, node2 retrieves WAL segment 117 from archive. It found a WAL record fragment at the end of the segment but could not find the remaining fragment in segment 118, so node2 stops recovery there.
LOG: restored log file "0000008C0000028C00000075" from archive
LOG: received promote request
LOG: redo done at 28C/75FFF7385. node2 becomes the primary, and its timeline becomes 118. node3 is disconnected by node2 (but later reconnectes to node2).
LOG: terminating all walsender processes to force cascaded standby(s) to update timeline and reconnect
6. node3 retrieves and applies WAL segment 117 from archive.
LOG: restored log file "0000008C0000028C00000075" from archive
7. node3 found .history file for time line 141 and renews its timeline to 141.
8. Because node3 found a WAL record fragment at the end of segment 117, it expects to find the remaining fragment at the beginning of WAL segment 118 streamed from node2. But there was a fragment of a different WAL record, because node2 overwrote a different WAL record at the end of segment 117 across to 118.
LOG: invalid contrecord length 5892 in log file 652, segment 118, offset 0
9. node3 then retrieves segment 117 from archive again to get the WAL record at the end of segment 117. However, as node3's timeline is already 141, it complains about the older timeline when it sees the timeline 140 at the beginning of segment 117.
LOG: out-of-sequence timeline ID 140 (after 141) in log file 652, segment 117, offset 0
OK. I agree that's a problem. However, your patch adds zero new
comment text while removing some existing comments, so I can't easily
tell how it solves that problem or whether it does so correctly. Even
if I were smart enough to figure it out, I wouldn't want to rely on
the next person also being that smart. This is obviously a subtle
problem in tricky code, so a clear explanation of the fix seems like a
very good idea.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Robert Haas
OK. I agree that's a problem. However, your patch adds zero new comment
text while removing some existing comments, so I can't easily tell how it
solves that problem or whether it does so correctly. Even if I were smart
enough to figure it out, I wouldn't want to rely on the next person also
being that smart. This is obviously a subtle problem in tricky code, so
a clear explanation of the fix seems like a very good idea.
The comment describes what the code is trying to achieve. Actually, I just imitated the code and comment of later major releases. The only difference between later releases and my patch (for 9.2) is whether the state is stored in XLogReaderStruct or as global variables. Below is the comment from 9.6, where the second paragraph describes what the two nested if conditions mean. The removed comment lines are what became irrelevant, which is also not present in later major releases.
/*
* Since child timelines are always assigned a TLI greater than their
* immediate parent's TLI, we should never see TLI go backwards across
* successive pages of a consistent WAL sequence.
*
* Sometimes we re-read a segment that's already been (partially) read. So
* we only verify TLIs for pages that are later than the last remembered
* LSN.
*/
Regards
Takayuki Tsunakawa
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Nov 10, 2016 at 10:43 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Robert Haas
OK. I agree that's a problem. However, your patch adds zero new comment
text while removing some existing comments, so I can't easily tell how it
solves that problem or whether it does so correctly. Even if I were smart
enough to figure it out, I wouldn't want to rely on the next person also
being that smart. This is obviously a subtle problem in tricky code, so
a clear explanation of the fix seems like a very good idea.The comment describes what the code is trying to achieve. Actually, I just imitated the code and comment of later major releases. The only difference between later releases and my patch (for 9.2) is whether the state is stored in XLogReaderStruct or as global variables. Below is the comment from 9.6, where the second paragraph describes what the two nested if conditions mean. The removed comment lines are what became irrelevant, which is also not present in later major releases.
/*
* Since child timelines are always assigned a TLI greater than their
* immediate parent's TLI, we should never see TLI go backwards across
* successive pages of a consistent WAL sequence.
*
* Sometimes we re-read a segment that's already been (partially) read. So
* we only verify TLIs for pages that are later than the last remembered
* LSN.
*/
I think the changes which you are referring has been done as part of
commit 7fcbf6a405ffc12a4546a25b98592ee6733783fc. There is no mention
of such a bug fix in that commit; however, it is quite possible that
such a change has fixed the problem you have reported. It is not
clear if we can directly copy that change and it seems to me the
change copied is also not complete. It looks like the code in 9.3 or
later version uses the recptr as the target segment location
(targetSegmentPtr) whereas 9.2 uses recptr as beginning of segment
(readOff = 0;). If above understanding is right then it will set
different values for latestPagePtr in 9.2 and 9.3 onwards code.
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Nov 10, 2016 at 12:13 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Robert Haas
OK. I agree that's a problem. However, your patch adds zero new comment
text while removing some existing comments, so I can't easily tell how it
solves that problem or whether it does so correctly. Even if I were smart
enough to figure it out, I wouldn't want to rely on the next person also
being that smart. This is obviously a subtle problem in tricky code, so
a clear explanation of the fix seems like a very good idea.The comment describes what the code is trying to achieve. Actually, I just imitated the code and comment of later major releases. The only difference between later releases and my patch (for 9.2) is whether the state is stored in XLogReaderStruct or as global variables. Below is the comment from 9.6, where the second paragraph describes what the two nested if conditions mean. The removed comment lines are what became irrelevant, which is also not present in later major releases.
Let me try to be more clear. I will not commit this patch if it is
not properly commented. I doubt that anyone else will, either.
The fact that those code changes already exist in 9.4+ is not a reason
to back-port them to earlier releases without a proper explanation of
why we are doing it. Very possibly, we should also improve the
comments in newer branches so that future authors don't reintroduce
whatever bugs were fixed by these changes. But whether we do that or
not, I am not going to commit uncommented patches to complex code in
order to fix obscure bugs in 3+-year-old branches. I think that is a
non-starter.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Amit Kapila
It looks like the code in 9.3 or later version uses the recptr as the target
segment location
(targetSegmentPtr) whereas 9.2 uses recptr as beginning of segment (readOff
= 0;). If above understanding is right then it will set different values
for latestPagePtr in 9.2 and 9.3 onwards code.
In 9.2, the relevant variable is not recptr but recaddr. recaddr in 9.2 and recptr in later releases point to the beginning of a page just read, which is not always the beginning of the segment (targetSegmentPtr).
Regards
Takayuki Tsunakawa
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Robert Haas
Let me try to be more clear. I will not commit this patch if it is not
properly commented. I doubt that anyone else will, either.The fact that those code changes already exist in 9.4+ is not a reason to
back-port them to earlier releases without a proper explanation of why we
are doing it. Very possibly, we should also improve the comments in newer
branches so that future authors don't reintroduce whatever bugs were fixed
by these changes. But whether we do that or not, I am not going to commit
uncommented patches to complex code in order to fix obscure bugs in
3+-year-old branches. I think that is a non-starter.
OK, although I'm not perfectly sure what to add as a comment, I added an example scenario as a comment because I thought a concrete situation helps to understand the existing two paragraphs. Is this good?
Regards
Takayuki Tsunakawa
Attachments:
cascading_standby_stuck_v2.patchapplication/octet-stream; name=cascading_standby_stuck_v2.patchDownload
diff -rc a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
*** a/src/backend/access/transam/xlog.c 2016-10-25 05:17:41.000000000 +0900
--- b/src/backend/access/transam/xlog.c 2016-11-15 12:26:35.000000000 +0900
***************
*** 589,596 ****
/* State information for XLOG reading */
static XLogRecPtr ReadRecPtr; /* start of last record read */
static XLogRecPtr EndRecPtr; /* end+1 of last record read */
! static TimeLineID lastPageTLI = 0;
! static TimeLineID lastSegmentTLI = 0;
static XLogRecPtr minRecoveryPoint; /* local copy of
* ControlFile->minRecoveryPoint */
--- 589,596 ----
/* State information for XLOG reading */
static XLogRecPtr ReadRecPtr; /* start of last record read */
static XLogRecPtr EndRecPtr; /* end+1 of last record read */
! static XLogRecPtr latestPagePtr; /* start of last page read */
! static TimeLineID latestPageTLI = 0;
static XLogRecPtr minRecoveryPoint; /* local copy of
* ControlFile->minRecoveryPoint */
***************
*** 678,684 ****
static void UpdateMinRecoveryPoint(XLogRecPtr lsn, bool force);
static XLogRecord *ReadRecord(XLogRecPtr *RecPtr, int emode, bool fetching_ckpt);
static void CheckRecoveryConsistency(void);
! static bool ValidXLOGHeader(XLogPageHeader hdr, int emode, bool segmentonly);
static XLogRecord *ReadCheckpointRecord(XLogRecPtr RecPtr, int whichChkpt);
static List *readTimeLineHistory(TimeLineID targetTLI);
static bool existsTimeLineHistory(TimeLineID probeTLI);
--- 678,684 ----
static void UpdateMinRecoveryPoint(XLogRecPtr lsn, bool force);
static XLogRecord *ReadRecord(XLogRecPtr *RecPtr, int emode, bool fetching_ckpt);
static void CheckRecoveryConsistency(void);
! static bool ValidXLOGHeader(XLogPageHeader hdr, int emode);
static XLogRecord *ReadCheckpointRecord(XLogRecPtr RecPtr, int whichChkpt);
static List *readTimeLineHistory(TimeLineID targetTLI);
static bool existsTimeLineHistory(TimeLineID probeTLI);
***************
*** 3992,4005 ****
(errmsg("invalid record offset at %X/%X",
RecPtr->xlogid, RecPtr->xrecoff)));
- /*
- * Since we are going to a random position in WAL, forget any prior
- * state about what timeline we were in, and allow it to be any
- * timeline in expectedTLIs. We also set a flag to allow curFileTLI
- * to go backwards (but we can't reset that variable right here, since
- * we might not change files at all).
- */
- lastPageTLI = lastSegmentTLI = 0; /* see comment in ValidXLOGHeader */
randAccess = true; /* allow curFileTLI to go backwards too */
}
--- 3992,3997 ----
***************
*** 4317,4323 ****
* ReadRecord. It's not intended for use from anywhere else.
*/
static bool
! ValidXLOGHeader(XLogPageHeader hdr, int emode, bool segmentonly)
{
XLogRecPtr recaddr;
--- 4309,4315 ----
* ReadRecord. It's not intended for use from anywhere else.
*/
static bool
! ValidXLOGHeader(XLogPageHeader hdr, int emode)
{
XLogRecPtr recaddr;
***************
*** 4411,4441 ****
* immediate parent's TLI, we should never see TLI go backwards across
* successive pages of a consistent WAL sequence.
*
! * Of course this check should only be applied when advancing sequentially
! * across pages; therefore ReadRecord resets lastPageTLI and
! * lastSegmentTLI to zero when going to a random page.
! *
! * Sometimes we re-open a segment that's already been partially replayed.
! * In that case we cannot perform the normal TLI check: if there is a
! * timeline switch within the segment, the first page has a smaller TLI
! * than later pages following the timeline switch, and we might've read
! * them already. As a weaker test, we still check that it's not smaller
! * than the TLI we last saw at the beginning of a segment. Pass
! * segmentonly = true when re-validating the first page like that, and the
! * page you're actually interested in comes later.
*/
! if (hdr->xlp_tli < (segmentonly ? lastSegmentTLI : lastPageTLI))
{
! ereport(emode_for_corrupt_record(emode, recaddr),
! (errmsg("out-of-sequence timeline ID %u (after %u) in log file %u, segment %u, offset %u",
! hdr->xlp_tli,
! segmentonly ? lastSegmentTLI : lastPageTLI,
! readId, readSeg, readOff)));
! return false;
}
! lastPageTLI = hdr->xlp_tli;
! if (readOff == 0)
! lastSegmentTLI = hdr->xlp_tli;
return true;
}
--- 4403,4447 ----
* immediate parent's TLI, we should never see TLI go backwards across
* successive pages of a consistent WAL sequence.
*
! * Sometimes we re-read a segment that's already been (partially) read. So
! * we only verify TLIs for pages that are later than the last remembered
! * LSN. An example of re-read which sees a smaller TLI is:
! *
! * In a streaming replication configuration where node1 is the primary,
! * node2 is the standby, and node3 is the cascading standby. They use a
! * shared WAL archive directory. node1's timeline is 1. It wrote a WAL
! * record at the end of WAL segment 10. The WAL record didn't fit the last
! * page, so it was split across segments 10 and 11. WAL segment 10 was
! * archived. node1 got down, and node2 is promoted. As part of the
! * recovery process, node2 retrieves WAL segment 10 from archive. It*
! * found a WAL record fragment at the end of the segment but could not
! * find the remaining fragment in segment 11, so node2 stops recovery
! * there. node2 becomes the primary, and its timeline becomes 2. node3 is
! * disconnected by node2 (but later reconnects to node2.) node3 retrieves
! * and applies WAL segment 10 from archive. node3 found .history file for
! * timeline 2 and renews its timeline to 2. Because node3 found a WAL
! * record fragment at the end of segment 10, it expects to find the
! * remaining fragment at the beginning of WAL segment 11 streamed from
! * node2. But there was a fragment of a different WAL record, because
! * node2 overwrote a different WAL record at the end of segment 10 across
! * to 11. node3 then retrieves segment 10 from archive again to get the
! * WAL record at the end of segment 10. While node3's timeline is already
! * 2, it sees the timeline 1 at the beginning of segment 10.
*/
! if (XLByteLT(latestPagePtr, recaddr))
{
! if (hdr->xlp_tli < latestPageTLI)
! {
! ereport(emode_for_corrupt_record(emode, recaddr),
! (errmsg("out-of-sequence timeline ID %u (after %u) in log file %u, segment %u, offset %u",
! hdr->xlp_tli,
! latestPageTLI,
! readId, readSeg, readOff)));
! return false;
! }
}
! latestPagePtr = recaddr;
! latestPageTLI = hdr->xlp_tli;
return true;
}
***************
*** 10817,10823 ****
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode, true))
goto next_record_is_invalid;
}
--- 10823,10829 ----
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode))
goto next_record_is_invalid;
}
***************
*** 10839,10845 ****
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode, false))
goto next_record_is_invalid;
Assert(targetId == readId);
--- 10845,10851 ----
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
! if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode))
goto next_record_is_invalid;
Assert(targetId == readId);
b/src/backend/access/transamだけに発見: xlog.c.orig
On Tue, Nov 15, 2016 at 7:51 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Amit Kapila
It looks like the code in 9.3 or later version uses the recptr as the target
segment location
(targetSegmentPtr) whereas 9.2 uses recptr as beginning of segment (readOff
= 0;). If above understanding is right then it will set different values
for latestPagePtr in 9.2 and 9.3 onwards code.In 9.2, the relevant variable is not recptr but recaddr. recaddr in 9.2 and recptr in later releases point to the beginning of a page just read, which is not always the beginning of the segment (targetSegmentPtr).
I think it beginning of segment (aka the first page of the segment),
even the comment indicates the same.
/*
* Whenever switching to a new WAL segment, we read the first page of
* the file and validate its header, even if that's not where the
* target record is. ...
..
*/
However, on again looking at the code, it seems that part of code
behaves similarly for both 9.2 and 9.3.
..Because node3 found a WAL
! * record fragment at the end of segment 10, it expects to find the
! * remaining fragment at the beginning of WAL segment 11 streamed from
! * node2. But there was a fragment of a different WAL record, because
! * node2 overwrote a different WAL record at the end of segment 10 across
! * to 11.
How does node3 ensure that the fragment of WAL in segment 11 is
different? Isn't it possible that when node2 overwrites the last
record in WAL segment 10, it writes a record of slightly different
contents but which is of the same size as an original record in WAL
segment 10?
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Amit Kapila
I think it beginning of segment (aka the first page of the segment), even
the comment indicates the same./*
* Whenever switching to a new WAL segment, we read the first page of
* the file and validate its header, even if that's not where the
* target record is. ...
..
*/However, on again looking at the code, it seems that part of code behaves
similarly for both 9.2 and 9.3.
Yes, the code behaves similarly in 9.2 and later. FYI, ValidXLogHeader() is called at two sites. The earlier one checks the first page of a segment when the real target page is different, and the latter one checks any page including the first page of a segment.
..Because node3 found a WAL
! * record fragment at the end of segment 10, it expects to find the !
* remaining fragment at the beginning of WAL segment 11 streamed from !
* node2. But there was a fragment of a different WAL record, because ! *
node2 overwrote a different WAL record at the end of segment 10 across !
* to 11.How does node3 ensure that the fragment of WAL in segment 11 is different?
Isn't it possible that when node2 overwrites the last record in WAL segment
10, it writes a record of slightly different contents but which is of the
same size as an original record in WAL segment 10?
That case is detected by checking the CRC value in the XLOG record header.
Regards
Takayuki Tsunakawa
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Mon, Sep 5, 2016 at 8:42 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Tsunakawa,
Our customer hit a problem of cascading replication, and we found the cause.
They are using the latest PostgreSQL 9.2.18. The bug seems to have been
fixed in 9.4 and higher during the big modification of xlog.c, but it's
not reflected in older releases.The attached patch is for 9.2.18. This just borrows the idea from 9.4 and
higher.But we haven't been able to reproduce the problem. Could you review the
patch and help to test it? I would very much appreciate it if you could
figure out how to reproduce the problem easily.We could successfully reproduce the problem and confirm that the patch fixes it. Please use the attached script to reproduce the problem.
I have tried using attached script multiple times on latest 9.2 code,
but couldn't reproduce the issue. Please find the log attached with
this mail. Apart from log file, below prints appear:
WARNING: enabling "trust" authentication for local connections
You can change this by editing pg_hba.conf or using the option -A, or
--auth-local and --auth-host, the next time you run initdb.
20075/20075 kB (100%), 1/1 tablespace
NOTICE: pg_stop_backup complete, all required WAL segments have been archived
20079/20079 kB (100%), 1/1 tablespace
Let me know, if some parameters need to be tweaked to reproduce the issue?
It seems that the patch proposed is good, but it is better if somebody
other than you can reproduce the issue and verify if the patch fixes
the same.
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
Attachments:
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Amit Kapila
I have tried using attached script multiple times on latest 9.2 code, but
couldn't reproduce the issue. Please find the log attached with this mail.
Apart from log file, below prints appear:WARNING: enabling "trust" authentication for local connections You can
change this by editing pg_hba.conf or using the option -A, or --auth-local
and --auth-host, the next time you run initdb.
20075/20075 kB (100%), 1/1 tablespace
NOTICE: pg_stop_backup complete, all required WAL segments have been
archived
20079/20079 kB (100%), 1/1 tablespaceLet me know, if some parameters need to be tweaked to reproduce the issue?
It seems that the patch proposed is good, but it is better if somebody other
than you can reproduce the issue and verify if the patch fixes the same.
Thank you for reviewing the code and testing. Hmm, we could reproduce the problem on PostgreSQL 9.2.19. The script's stdout is attached as test.log, and the stderr is as follows:
WARNING: enabling "trust" authentication for local connections You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.
20099/20099 kB (100%), 1/1 tablespace
NOTICE: pg_stop_backup complete, all required WAL segments have been archived
20103/20103 kB (100%), 1/1 tablespace
The sizes pg_basebackup outputs is a bit different from yours. I don't see a reason for this. The test script explicitly specifies the database encoding and locale, so the encoding difference doesn't seem to be the cause. The target problem occurs only when a WAL record crosses a WAL segment boundary, so subtle change in WAL record volume would prevent the problem from happening.
Anyway, could you retry with the attached test.sh? It just changes restore_command.
If the problem occurs, the following pair of lines appear in the server log of the cascading standby. Could you check it?
LOG: restored log file "000000020000000000000003" from archive
LOG: out-of-sequence timeline ID 1 (after 2) in log file 0, segment 3, offset 0
Regards
Takayuki Tsunakawa
On Tue, Nov 22, 2016 at 8:48 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
From: pgsql-hackers-owner@postgresql.org
If the problem occurs, the following pair of lines appear in the server log of the cascading standby. Could you check it?
LOG: restored log file "000000020000000000000003" from archive
LOG: out-of-sequence timeline ID 1 (after 2) in log file 0, segment 3, offset 0
Thanks for the clarification, I could reproduce the issue and confirms
that patch has fixed it. Find logs of cascading standby at PG9.2
Head and Patch attached (I have truncated few lines at end of server
log generated in Head as those were repetitive). I think the way you
have directly explained the bug steps in code comments is not right
(think if we start writing bug steps for each bug fix, how the code
will look like). So I have modified the comment to explain the
situation and reason of check, see if you find that as okay?
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
Attachments:
cascading_standby_stuck_v3.patchapplication/octet-stream; name=cascading_standby_stuck_v3.patchDownload
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 312a3e3..4981883 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -592,8 +592,8 @@ static uint32 readRecordBufSize = 0;
/* State information for XLOG reading */
static XLogRecPtr ReadRecPtr; /* start of last record read */
static XLogRecPtr EndRecPtr; /* end+1 of last record read */
-static TimeLineID lastPageTLI = 0;
-static TimeLineID lastSegmentTLI = 0;
+static XLogRecPtr latestPagePtr; /* start of last page read */
+static TimeLineID latestPageTLI = 0;
static XLogRecPtr minRecoveryPoint; /* local copy of
* ControlFile->minRecoveryPoint */
@@ -681,7 +681,7 @@ static void CleanupBackupHistory(void);
static void UpdateMinRecoveryPoint(XLogRecPtr lsn, bool force);
static XLogRecord *ReadRecord(XLogRecPtr *RecPtr, int emode, bool fetching_ckpt);
static void CheckRecoveryConsistency(void);
-static bool ValidXLOGHeader(XLogPageHeader hdr, int emode, bool segmentonly);
+static bool ValidXLOGHeader(XLogPageHeader hdr, int emode);
static XLogRecord *ReadCheckpointRecord(XLogRecPtr RecPtr, int whichChkpt);
static List *readTimeLineHistory(TimeLineID targetTLI);
static bool existsTimeLineHistory(TimeLineID probeTLI);
@@ -3995,14 +3995,6 @@ ReadRecord(XLogRecPtr *RecPtr, int emode, bool fetching_ckpt)
(errmsg("invalid record offset at %X/%X",
RecPtr->xlogid, RecPtr->xrecoff)));
- /*
- * Since we are going to a random position in WAL, forget any prior
- * state about what timeline we were in, and allow it to be any
- * timeline in expectedTLIs. We also set a flag to allow curFileTLI
- * to go backwards (but we can't reset that variable right here, since
- * we might not change files at all).
- */
- lastPageTLI = lastSegmentTLI = 0; /* see comment in ValidXLOGHeader */
randAccess = true; /* allow curFileTLI to go backwards too */
}
@@ -4320,7 +4312,7 @@ next_record_is_invalid:
* ReadRecord. It's not intended for use from anywhere else.
*/
static bool
-ValidXLOGHeader(XLogPageHeader hdr, int emode, bool segmentonly)
+ValidXLOGHeader(XLogPageHeader hdr, int emode)
{
XLogRecPtr recaddr;
@@ -4414,31 +4406,25 @@ ValidXLOGHeader(XLogPageHeader hdr, int emode, bool segmentonly)
* immediate parent's TLI, we should never see TLI go backwards across
* successive pages of a consistent WAL sequence.
*
- * Of course this check should only be applied when advancing sequentially
- * across pages; therefore ReadRecord resets lastPageTLI and
- * lastSegmentTLI to zero when going to a random page.
- *
- * Sometimes we re-open a segment that's already been partially replayed.
- * In that case we cannot perform the normal TLI check: if there is a
- * timeline switch within the segment, the first page has a smaller TLI
- * than later pages following the timeline switch, and we might've read
- * them already. As a weaker test, we still check that it's not smaller
- * than the TLI we last saw at the beginning of a segment. Pass
- * segmentonly = true when re-validating the first page like that, and the
- * page you're actually interested in comes later.
+ * Sometimes we re-read a segment that's already been (partially) read.
+ * This can happen when we read WAL segments from parent's TLI during
+ * archive recovery, refer XLogFileReadAnyTLI. So we only verify TLIs
+ * for pages that are later than the last remembered LSN.
*/
- if (hdr->xlp_tli < (segmentonly ? lastSegmentTLI : lastPageTLI))
+ if (XLByteLT(latestPagePtr, recaddr))
{
- ereport(emode_for_corrupt_record(emode, recaddr),
- (errmsg("out-of-sequence timeline ID %u (after %u) in log file %u, segment %u, offset %u",
- hdr->xlp_tli,
- segmentonly ? lastSegmentTLI : lastPageTLI,
- readId, readSeg, readOff)));
- return false;
+ if (hdr->xlp_tli < latestPageTLI)
+ {
+ ereport(emode_for_corrupt_record(emode, recaddr),
+ (errmsg("out-of-sequence timeline ID %u (after %u) in log file %u, segment %u, offset %u",
+ hdr->xlp_tli,
+ latestPageTLI,
+ readId, readSeg, readOff)));
+ return false;
+ }
}
- lastPageTLI = hdr->xlp_tli;
- if (readOff == 0)
- lastSegmentTLI = hdr->xlp_tli;
+ latestPagePtr = recaddr;
+ latestPageTLI = hdr->xlp_tli;
return true;
}
@@ -10842,7 +10828,7 @@ retry:
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
- if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode, true))
+ if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode))
goto next_record_is_invalid;
}
@@ -10864,7 +10850,7 @@ retry:
readId, readSeg, readOff)));
goto next_record_is_invalid;
}
- if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode, false))
+ if (!ValidXLOGHeader((XLogPageHeader) readBuf, emode))
goto next_record_is_invalid;
Assert(targetId == readId);
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Amit Kapila
Thanks for the clarification, I could reproduce the issue and confirms that
patch has fixed it. Find logs of cascading standby at PG9.2 Head and Patch
attached (I have truncated few lines at end of server log generated in Head
as those were repetitive). I think the way you have directly explained
the bug steps in code comments is not right (think if we start writing bug
steps for each bug fix, how the code will look like). So I have modified
the comment to explain the situation and reason of check, see if you find
that as okay?
Thank you, I'm happy with your comment.
Regards
Takayuki Tsunakawa
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Nov 24, 2016 at 10:29 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:
From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Amit Kapila
Thanks for the clarification, I could reproduce the issue and confirms that
patch has fixed it. Find logs of cascading standby at PG9.2 Head and Patch
attached (I have truncated few lines at end of server log generated in Head
as those were repetitive). I think the way you have directly explained
the bug steps in code comments is not right (think if we start writing bug
steps for each bug fix, how the code will look like). So I have modified
the comment to explain the situation and reason of check, see if you find
that as okay?Thank you, I'm happy with your comment.
Okay, I have marked the patch as 'Ready for Committer'.
--
With Regards,
Amit Kapila.
EnterpriseDB: http://www.enterprisedb.com
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
On Thu, Nov 24, 2016 at 4:24 PM, Amit Kapila <amit.kapila16@gmail.com> wrote:
On Thu, Nov 24, 2016 at 10:29 AM, Tsunakawa, Takayuki
<tsunakawa.takay@jp.fujitsu.com> wrote:From: pgsql-hackers-owner@postgresql.org
[mailto:pgsql-hackers-owner@postgresql.org] On Behalf Of Amit Kapila
Thanks for the clarification, I could reproduce the issue and confirms that
patch has fixed it. Find logs of cascading standby at PG9.2 Head and Patch
attached (I have truncated few lines at end of server log generated in Head
as those were repetitive). I think the way you have directly explained
the bug steps in code comments is not right (think if we start writing bug
steps for each bug fix, how the code will look like). So I have modified
the comment to explain the situation and reason of check, see if you find
that as okay?Thank you, I'm happy with your comment.
Okay, I have marked the patch as 'Ready for Committer'.
Pushed. Thanks!
Regards,
--
Fujii Masao
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers