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

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:
/messages/by-id/CABOikdPsPByMiG6J01DKq6om2+BNkxHTPkOyqHM2a4oYwGKsqQ@mail.gmail.com

Reminds me as well of the following:
/messages/by-id/CAOR=d=16x+jKM=00AoEZEKU9RJDwjU9E2bUnFBpX_HrGjkMHXg@mail.gmail.com
--
Michael

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

On Wed, Nov 6, 2019 at 2:07 PM Andrey Lepikhov
<a.lepikhov@postgrespro.ru> 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

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

On Thu, Nov 7, 2019 at 12:41 PM Michael Paquier <michael@paquier.xyz> 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

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