The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
7 messages Options
Reply | Threaded
Open this post in threaded view
|

The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Andrey Lepikhov
I found this in our multimaster project on PostgreSQL 11.5. It is
difficult to reproduce this error, but I will try to do it if necessary.

The rest of a continuation WAL-record can exactly match the block size.
In this case, we need to switch targetPagePtr to the next block before
calculating the starting point of the next WAL-record.
See the patch in attachment for the bug fix.

--
Andrey Lepikhov
Postgres Professional
https://postgrespro.com
The Russian Postgres Company

0001-Correct-the-algorithm-of-definition-of-WAL-record-st.patch (1K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Michael Paquier-2
On Wed, Nov 06, 2019 at 07:40:48AM +0500, Andrey Lepikhov wrote:
> I found this in our multimaster project on PostgreSQL 11.5. It is difficult
> to reproduce this error, but I will try to do it if necessary.
>
> The rest of a continuation WAL-record can exactly match the block size. In
> this case, we need to switch targetPagePtr to the next block before
> calculating the starting point of the next WAL-record.
> See the patch in attachment for the bug fix.

What's the error you actually saw after reading the record in
xlogreader.c?  If you have past WAL archives, perhaps you are able to
reproduce the problem with a given WAL segment and pg_waldump?

This code rings a bell as of this thread which led to commit bab7823:
https://www.postgresql.org/message-id/CABOikdPsPByMiG6J01DKq6om2+BNkxHTPkOyqHM2a4oYwGKsqQ@...

Reminds me as well of the following:
https://www.postgresql.org/message-id/CAOR=d=16x+jKM=00AoEZEKU9RJDwjU9E2bUnFBpX_HrGjkMHXg@...
--
Michael

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Andrey Lepikhov


On 06/11/2019 09:41, Michael Paquier wrote:

> On Wed, Nov 06, 2019 at 07:40:48AM +0500, Andrey Lepikhov wrote:
>> I found this in our multimaster project on PostgreSQL 11.5. It is difficult
>> to reproduce this error, but I will try to do it if necessary.
>>
>> The rest of a continuation WAL-record can exactly match the block size. In
>> this case, we need to switch targetPagePtr to the next block before
>> calculating the starting point of the next WAL-record.
>> See the patch in attachment for the bug fix.
>
> What's the error you actually saw after reading the record in
> xlogreader.c?  If you have past WAL archives, perhaps you are able to
> reproduce the problem with a given WAL segment and pg_waldump?

I saw the message:
pg_waldump: xlogreader.c:264: XLogReadRecord: <Text in russian>
"((RecPtr) % 8192 >= (((uintptr_t) ((sizeof(XLogPageHeaderData))) + ((8)
- 1)) & ~((uintptr_t) ((8) - 1))))" <Text in russian>

Yes, I reproduced error with pg_waldump too. The patch in previous
letter fixed this problem.

some details:
I have the record:
rmgr: Transaction len (rec/tot): 86/ 86, tx: 0, lsn: 0/11FFFF98, prev
0/11FFFDA8, desc: COMMIT_PREPARED

The next record occupied the rest of segment No.11 and 8151 bytes of the
first block of the segment No.12, i.e. its size is 8167 bytes.

Problematic record (I got it by pg_waldump after applying the patch) is:
rmgr: Heap len (rec/tot): 71/ 8167, tx: 1249835485258, lsn: 0/11FFFFF0,
prev 0/11FFFF98, desc: LOCK off 8: xid 1249835485258: flags 0 LOCK_ONLY
EXCL_LOCK KEYS_UPDATED , blkref #0: rel 1663/13121/16474 blk 10880 FPW

--
Andrey Lepikhov
Postgres Professional
https://postgrespro.com
The Russian Postgres Company


Reply | Threaded
Open this post in threaded view
|

Re: The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Fujii Masao-2
On Wed, Nov 6, 2019 at 2:07 PM Andrey Lepikhov
<[hidden email]> wrote:

>
>
>
> On 06/11/2019 09:41, Michael Paquier wrote:
> > On Wed, Nov 06, 2019 at 07:40:48AM +0500, Andrey Lepikhov wrote:
> >> I found this in our multimaster project on PostgreSQL 11.5. It is difficult
> >> to reproduce this error, but I will try to do it if necessary.
> >>
> >> The rest of a continuation WAL-record can exactly match the block size. In
> >> this case, we need to switch targetPagePtr to the next block before
> >> calculating the starting point of the next WAL-record.
> >> See the patch in attachment for the bug fix.
Good catch!

> > What's the error you actually saw after reading the record in
> > xlogreader.c?  If you have past WAL archives, perhaps you are able to
> > reproduce the problem with a given WAL segment and pg_waldump?
>
> I saw the message:
> pg_waldump: xlogreader.c:264: XLogReadRecord: <Text in russian>
> "((RecPtr) % 8192 >= (((uintptr_t) ((sizeof(XLogPageHeaderData))) + ((8)
> - 1)) & ~((uintptr_t) ((8) - 1))))" <Text in russian>

I created the problematic WAL file artificially by using
pg_logical_emit_message() and sucessfully reproduced
the error. I attached the WAL file that I created. You can
reproduce the issue by

    pg_waldump 000000010000000000000008 -s 0/08002028

> Yes, I reproduced error with pg_waldump too. The patch in previous
> letter fixed this problem.

The patch looks good to me. Barrying any objection, I will commit it.
XLogFindNextRecord() must return the valid record starting position,
but currently could return the starting position of WAL page
(not valid WAL record) in the case that you described. This is
the cause of the issue.

Regards,

--
Fujii Masao

000000010000000000000008.tar.bz2 (430 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Michael Paquier-2
On Thu, Nov 07, 2019 at 02:41:29AM +0900, Fujii Masao wrote:
> I created the problematic WAL file artificially by using
> pg_logical_emit_message() and sucessfully reproduced
> the error.

Good idea.  I didn't know this one.

> I attached the WAL file that I created. You can
> reproduce the issue by
>
>     pg_waldump 000000010000000000000008 -s 0/08002028

Assertion failure reproduced here.

> The patch looks good to me. Barrying any objection, I will commit it.
> XLogFindNextRecord() must return the valid record starting position,
> but currently could return the starting position of WAL page
> (not valid WAL record) in the case that you described. This is
> the cause of the issue.

No issues from here, thanks for taking care of it.
--
Michael

signature.asc (849 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Fujii Masao-2
On Thu, Nov 7, 2019 at 12:41 PM Michael Paquier <[hidden email]> wrote:

>
> On Thu, Nov 07, 2019 at 02:41:29AM +0900, Fujii Masao wrote:
> > I created the problematic WAL file artificially by using
> > pg_logical_emit_message() and sucessfully reproduced
> > the error.
>
> Good idea.  I didn't know this one.
>
> > I attached the WAL file that I created. You can
> > reproduce the issue by
> >
> >     pg_waldump 000000010000000000000008 -s 0/08002028
>
> Assertion failure reproduced here.
>
> > The patch looks good to me. Barrying any objection, I will commit it.
> > XLogFindNextRecord() must return the valid record starting position,
> > but currently could return the starting position of WAL page
> > (not valid WAL record) in the case that you described. This is
> > the cause of the issue.
>
> No issues from here, thanks for taking care of it.

Thanks for the check! I committed the patch!

Regards,

--
Fujii Masao


Reply | Threaded
Open this post in threaded view
|

Re: The XLogFindNextRecord() routine find incorrect record start point after a long continuation record

Michael Paquier-2
On Thu, Nov 07, 2019 at 04:37:00PM +0900, Fujii Masao wrote:
> Thanks for the check! I committed the patch!

Thanks Fujii-san.
--
Michael

signature.asc (849 bytes) Download Attachment