Content-Type: multipart/mixed; boundary="------------81Fv6q9XhyBxDfR8RT0cz20M"
Message-ID: <b26aeac2-cb6d-4633-a7ea-945baae83dcf@postgrespro.ru>
Date: Thu, 18 Jan 2024 15:47:22 +0300
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Content-Language: en-US
To: Pg Hackers <pgsql-hackers@postgresql.org>
Cc: Thomas Munro <thomas.munro@gmail.com>
From: Anton Voloshin <a.voloshin@postgrespro.ru>
Subject: 039_end_of_wal: error in "xl_tot_len zero" test
Archived-At: 
 <https://www.postgresql.org/message-id/b26aeac2-cb6d-4633-a7ea-945baae83dcf%40postgrespro.ru>
Precedence: bulk

This is a multi-part message in MIME format.
--------------81Fv6q9XhyBxDfR8RT0cz20M
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 7bit

Hello, hackers,

I believe there is a small problem in the 039_end_of_wal.pl's 
"xl_tot_len zero" test. It supposes that after immediate shutdown the 
server, upon startup recovery, should always produce a message matching 
"invalid record length at .*: wanted 24, got 0". However, if the 
circumstances are just right and we happened to hit exactly on the edge 
of WAL page, then the message on startup recovery would be "invalid 
magic number 0000 in log segment .*, offset .*". The test does not take 
that into account.

Now, reproducing this is somewhat tricky, because exact position in WAL 
at the test time depends on what exactly initdb did, and that not only 
differs in different major verisons, but also depends on e.g. username 
length, locales available, and, perhaps, more. Even though originally 
this problem was found "in the wild" on one particular system on one 
particular code branch, I've written small helper patch to make 
reproduction on master easier, see 
0001-repro-for-039_end_of_wal-s-problem-with-page-end.patch.

This patch adds single emit_message of (hopefully) the right size to 
make sure we hit end of WAL block right by the time we call 
$node->stop('immediate') in "xl_tot_len zero" test. With this patch, 
"xl_tot_len zero" test fails every time because the server writes 
"invalid magic number 0000 in log segment" while the test still only 
expects "invalid record length at .*: wanted 24, got 0". If course, this 
0001 patch is *not* meant to be committed, but only as an issue 
reproduction helper.

I can think of two possible fixes:

1. Update advance_out_of_record_splitting_zone to also avoid stopping at
    exactly the block end:

      my $page_offset = $end_lsn % $WAL_BLOCK_SIZE;
-    while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold)
+    while ($page_offset >= $WAL_BLOCK_SIZE - $page_threshold || 
$page_offset <= $SizeOfXLogShortPHD)
      {
see 0002-fix-xl_tot_len-zero-test-amend-advance_out_of.patch

We need to compare with $SizeOfXLogShortPHD (and not with zero) because 
at that point, even though we didn't actually write out new WAL page
yet, it's header is already in place in memory and taken in account
for LSN reporting.

2. Alternatively, amend "xl_tot_len zero" test to expect "invalid magic
    number 0000 in WAL segment" message as well:

  $node->start;
  ok( $node->log_contains(
+        "invalid magic number 0000 in WAL segment|" .
          "invalid record length at .*: expected at least 24, got 0", 
$log_size
      ),
see 0003-alt.fix-for-xl_tot_len-zero-test-accept-invalid.patch

I think it makes sense to backport whatever the final change would be to 
all branches with 039_end_of_wal (REL_12+).

Any thoughts?

Anton Voloshin
Postgres Professional, The Russian Postgres Company
https://postgrespro.ru
--------------81Fv6q9XhyBxDfR8RT0cz20M
Content-Type: text/x-patch; charset=UTF-8;
 name="0001-repro-for-039_end_of_wal-s-problem-with-page-end.patch"
Content-Disposition: attachment;
 filename*0="0001-repro-for-039_end_of_wal-s-problem-with-page-end.patch"
Content-Transfer-Encoding: base64

RnJvbSA1ZjEyMTM5ODE2ZjZjMWJjN2Q2MjViYTgwMDdhZWRiOGY1ZDA0YTcxIE1vbiBTZXAg
MTcgMDA6MDA6MDAgMjAwMQpGcm9tOiBBbnRvbiBWb2xvc2hpbiA8YS52b2xvc2hpbkBwb3N0
Z3Jlc3Byby5ydT4KRGF0ZTogVGh1LCAxOCBKYW4gMjAyNCAxMjo0NToxMiArMDMwMApTdWJq
ZWN0OiBbUEFUQ0ggMS8zXSByZXBybyBmb3IgMDM5X2VuZF9vZl93YWwncyBwcm9ibGVtIHdp
dGggcGFnZQogZW5kCgpUYWdzOiBjb21taXRmZXN0X2hvdGZpeAotLS0KIHNyYy90ZXN0L3Jl
Y292ZXJ5L3QvMDM5X2VuZF9vZl93YWwucGwgfCAyMCArKysrKysrKysrKysrKysrKysrKwog
MSBmaWxlIGNoYW5nZWQsIDIwIGluc2VydGlvbnMoKykKCmRpZmYgLS1naXQgYS9zcmMvdGVz
dC9yZWNvdmVyeS90LzAzOV9lbmRfb2Zfd2FsLnBsIGIvc3JjL3Rlc3QvcmVjb3ZlcnkvdC8w
MzlfZW5kX29mX3dhbC5wbAppbmRleCBmOWFjYzgzYzdkMC4uZWNmOWI2MDg5ZGUgMTAwNjQ0
Ci0tLSBhL3NyYy90ZXN0L3JlY292ZXJ5L3QvMDM5X2VuZF9vZl93YWwucGwKKysrIGIvc3Jj
L3Rlc3QvcmVjb3ZlcnkvdC8wMzlfZW5kX29mX3dhbC5wbApAQCAtMzYsNiArMzYsOCBAQCBt
eSAkV0FMX1NFR01FTlRfU0laRTsKIG15ICRXQUxfQkxPQ0tfU0laRTsKIG15ICRUTEk7CiAK
K215ICRTaXplT2ZYTG9nU2hvcnRQSEQgPSAyNDsgIyByb3VuZGVkIHVwIHRvIDggYnl0ZXMK
KwogIyBCdWlsZCBwYXRoIG9mIGEgV0FMIHNlZ21lbnQuCiBzdWIgd2FsX3NlZ21lbnRfcGF0
aAogewpAQCAtMjU4LDkgKzI2MCwyNyBAQCBteSAkcHJldl9sc247CiBub3RlICJTaW5nbGUt
cGFnZSBlbmQtb2YtV0FMIGRldGVjdGlvbiI7CiAjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMj
IyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMjIyMKIAor
bXkgJGxzbiA9IGdldF9pbnNlcnRfbHNuKCRub2RlKTsKK215ICRsc25fb2Zmc2V0ID0gJGxz
biAlICRXQUxfQkxPQ0tfU0laRTsKK215ICRlbXB0eV9tc2dfc2l6ZSA9ICggKCAoJEVOVntF
TVBUWV9NU0dfU0laRX0gfHwgNTEpICsgNykgLyA4KSAqIDg7CitteSAkY29tbWl0X21zZ19z
aXplID0gKCAoMzQgKyA3KSAvIDgpICogODsKKyMgZW1wdHkgbG9naWNhbCBtc2cgYW5kIGNv
bW1pdCBtZXNzYWdlIHRha2UgdGhpcyBtYW55IGJ5dGVzIG9mIFdBTDoKK215ICRlbXB0eV9t
c2dfb3ZlcmhlYWQgPSAkZW1wdHlfbXNnX3NpemUgKyAkY29tbWl0X21zZ19zaXplOworIyBj
b3VuZCBvdmVyaGVhZCB0d2ljZSB0byBhY2NvdW50IGZvciB0d28gZW1pdF9tZXNzYWdlIGNh
bGxzIGJlbG93OgorIyB3ZSB3YW50IHRvIGhpdCB0aGUgcGFnZSBlZGdlIGFmdGVyIHRoZSBz
ZWNvbmQgY2FsbC4KK215ICR0YXJnZXRfbHNuX29mZnNldCA9ICRXQUxfQkxPQ0tfU0laRSAq
IDIgLSAkZW1wdHlfbXNnX292ZXJoZWFkICogMjsKK215ICRtc2dfc2l6ZSA9ICgkdGFyZ2V0
X2xzbl9vZmZzZXQgLSAkbHNuX29mZnNldCkgJSAkV0FMX0JMT0NLX1NJWkU7CisjIElmIHdl
IGhhcHBlbiB0byBzd2l0Y2ggdG8gdGhlIG5leHQgV0FMIGJsb2NrIG1pZC1tZXNzYWdlLCBy
ZWR1Y2UgdGhlIG1lc3NhZ2UKKyMgYnkgJFNpemVPZlhMb2dTaG9ydFBIRCAobWluaW1hbCBw
YWdlIGhlYWRlcikgdG8gaGl0IHRoZSBzYW1lIHRhcmdldC4KK2lmICgkbHNuX29mZnNldCAr
ICRtc2dfc2l6ZSA+PSAkV0FMX0JMT0NLX1NJWkUpIHsgJG1zZ19zaXplIC09ICRTaXplT2ZY
TG9nU2hvcnRQSEQ7IH0KK3ByaW50ICJRV0UwOiAkbHNuIFdBTF9CTE9DS19TSVpFPSckV0FM
X0JMT0NLX1NJWkUnLCBsc25fb2Zmc2V0PSckbHNuX29mZnNldCcgdGFyZ2V0X2xzbl9vZmZz
ZXQ9JyR0YXJnZXRfbHNuX29mZnNldCcgbXNnX3NpemU9JyRtc2dfc2l6ZSdcbiI7CitlbWl0
X21lc3NhZ2UoJG5vZGUsICRtc2dfc2l6ZSk7CitwcmludGYgIlFXRTE6ICVzIC0gYWZ0ZXIg
Y29ycmVjdGl2ZSBtc2dcbiIsICRub2RlLT5zYWZlX3BzcWwoJ3Bvc3RncmVzJywgIlNFTEVD
VCBwZ19jdXJyZW50X3dhbF9sc24oKSIpOwogIyB4bF90b3RfbGVuIGlzIDAgKGEgY29tbW9u
IGNhc2UsIHdlIGhpdCB0cmFpbGluZyB6ZXJvZXMpLgogZW1pdF9tZXNzYWdlKCRub2RlLCAw
KTsKK3ByaW50ZiAiUVdFMjogJXMgLSBhZnRlciB6ZXJvLWxlbmd0aCBtZXNzYWdlXG4iLCAk
bm9kZS0+c2FmZV9wc3FsKCdwb3N0Z3JlcycsICJTRUxFQ1QgcGdfY3VycmVudF93YWxfbHNu
KCkiKTsKICRlbmRfbHNuID0gYWR2YW5jZV9vdXRfb2ZfcmVjb3JkX3NwbGl0dGluZ196b25l
KCRub2RlKTsKK3ByaW50ZiAiUVdFMzogJXMgLSBhZnRlciBhZHZhbmNlX291dF9vZl9yZWNv
cmRfc3BsaXR0aW5nX3N6b25lKClcbiIsICRub2RlLT5zYWZlX3BzcWwoJ3Bvc3RncmVzJywg
IlNFTEVDVCBwZ19jdXJyZW50X3dhbF9sc24oKSIpOwogJG5vZGUtPnN0b3AoJ2ltbWVkaWF0
ZScpOwogbXkgJGxvZ19zaXplID0gLXMgJG5vZGUtPmxvZ2ZpbGU7CiAkbm9kZS0+c3RhcnQ7
Ci0tIAoyLjQzLjAKCg==
--------------81Fv6q9XhyBxDfR8RT0cz20M
Content-Type: text/x-patch; charset=UTF-8;
 name="0002-fix-xl_tot_len-zero-test-amend-advance_out_of.patch"
Content-Disposition: attachment;
 filename="0002-fix-xl_tot_len-zero-test-amend-advance_out_of.patch"
Content-Transfer-Encoding: base64

RnJvbSBlZWJiYzc1NWM4ODAwNzExOTRiYmQwMjgyNWI0YzQ3ZjExZjk5MjEzIE1vbiBTZXAg
MTcgMDA6MDA6MDAgMjAwMQpGcm9tOiBBbnRvbiBWb2xvc2hpbiA8YS52b2xvc2hpbkBwb3N0
Z3Jlc3Byby5ydT4KRGF0ZTogVGh1LCAxOCBKYW4gMjAyNCAxNDo0Nzo1MiArMDMwMApTdWJq
ZWN0OiBbUEFUQ0ggMi8zXSBmaXggInhsX3RvdF9sZW4gemVybyIgdGVzdDogYW1lbmQKIGFk
dmFuY2Vfb3V0X29mX3JlY29yZF9zcGxpdHRpbmdfem9uZQoKVGFnczogY29tbWl0ZmVzdF9o
b3RmaXgKLS0tCiBzcmMvdGVzdC9yZWNvdmVyeS90LzAzOV9lbmRfb2Zfd2FsLnBsIHwgNCAr
KystCiAxIGZpbGUgY2hhbmdlZCwgMyBpbnNlcnRpb25zKCspLCAxIGRlbGV0aW9uKC0pCgpk
aWZmIC0tZ2l0IGEvc3JjL3Rlc3QvcmVjb3ZlcnkvdC8wMzlfZW5kX29mX3dhbC5wbCBiL3Ny
Yy90ZXN0L3JlY292ZXJ5L3QvMDM5X2VuZF9vZl93YWwucGwKaW5kZXggZWNmOWI2MDg5ZGUu
LjMxNjhkOTkxZmVlIDEwMDY0NAotLS0gYS9zcmMvdGVzdC9yZWNvdmVyeS90LzAzOV9lbmRf
b2Zfd2FsLnBsCisrKyBiL3NyYy90ZXN0L3JlY292ZXJ5L3QvMDM5X2VuZF9vZl93YWwucGwK
QEAgLTE3Myw2ICsxNzMsOCBAQCBzdWIgYnVpbGRfcGFnZV9oZWFkZXIKICMgYSBjb3VwbGUg
b2Ygc21hbGwgcmVjb3Jkcy4gIFRoaXMgaW5zZXJ0cyBhIGZldyByZWNvcmRzIG9mIGEgZml4
ZWQgc2l6ZSwgdW50aWwKICMgdGhlIHRocmVzaG9sZCBnZXRzIGNsb3NlIGVub3VnaCB0byB0
aGUgZW5kIG9mIHRoZSBXQUwgcGFnZSBpbnNlcnRpbmcgcmVjb3JkcwogIyB0by4KKyMgQWxz
byBhdm9pZCB0aGUgdmVyeSBiZWdpbm5pbmcgb2YgYSBwYWdlOiB0aGF0IHdvdWxkIGJyZWFr
IGEgdGVzdCBmb3IgYQorIyB6ZXJvLWxlbmd0aCBsb2dpY2FsIG1lc3NhZ2UuCiBzdWIgYWR2
YW5jZV9vdXRfb2ZfcmVjb3JkX3NwbGl0dGluZ196b25lCiB7CiAJbXkgJG5vZGUgPSBzaGlm
dDsKQEAgLTE4MCw3ICsxODIsNyBAQCBzdWIgYWR2YW5jZV9vdXRfb2ZfcmVjb3JkX3NwbGl0
dGluZ196b25lCiAJbXkgJHBhZ2VfdGhyZXNob2xkID0gJFdBTF9CTE9DS19TSVpFIC8gNDsK
IAlteSAkZW5kX2xzbiA9IGdldF9pbnNlcnRfbHNuKCRub2RlKTsKIAlteSAkcGFnZV9vZmZz
ZXQgPSAkZW5kX2xzbiAlICRXQUxfQkxPQ0tfU0laRTsKLQl3aGlsZSAoJHBhZ2Vfb2Zmc2V0
ID49ICRXQUxfQkxPQ0tfU0laRSAtICRwYWdlX3RocmVzaG9sZCkKKwl3aGlsZSAoJHBhZ2Vf
b2Zmc2V0ID49ICRXQUxfQkxPQ0tfU0laRSAtICRwYWdlX3RocmVzaG9sZCB8fCAkcGFnZV9v
ZmZzZXQgPD0gJFNpemVPZlhMb2dTaG9ydFBIRCkKIAl7CiAJCWVtaXRfbWVzc2FnZSgkbm9k
ZSwgJHBhZ2VfdGhyZXNob2xkKTsKIAkJJGVuZF9sc24gPSBnZXRfaW5zZXJ0X2xzbigkbm9k
ZSk7Ci0tIAoyLjQzLjAKCg==
--------------81Fv6q9XhyBxDfR8RT0cz20M
Content-Type: text/x-patch; charset=UTF-8;
 name="0003-alt.fix-for-xl_tot_len-zero-test-accept-invalid.patch"
Content-Disposition: attachment;
 filename*0="0003-alt.fix-for-xl_tot_len-zero-test-accept-invalid.patch"
Content-Transfer-Encoding: base64

RnJvbSAyNDE5ZWM2NzgwZjFlNmEwMDNiNTUzMDY2ZjgzZDk2NmZlZTBjMTViIE1vbiBTZXAg
MTcgMDA6MDA6MDAgMjAwMQpGcm9tOiBBbnRvbiBWb2xvc2hpbiA8YS52b2xvc2hpbkBwb3N0
Z3Jlc3Byby5ydT4KRGF0ZTogVGh1LCAxOCBKYW4gMjAyNCAxNTowMzoxMSArMDMwMApTdWJq
ZWN0OiBbUEFUQ0ggMy8zXSBhbHQuZml4IGZvciAieGxfdG90X2xlbiB6ZXJvIiB0ZXN0OiBh
Y2NlcHQKICJpbnZhbGlkIG1hZ2ljIG51bWJlciAwMDAwIGluIFdBTCBzZWdtZW50IiBhcyB3
ZWxsCgpUYWdzOiBjb21taXRmZXN0X2hvdGZpeAotLS0KIHNyYy90ZXN0L3JlY292ZXJ5L3Qv
MDM5X2VuZF9vZl93YWwucGwgfCAxICsKIDEgZmlsZSBjaGFuZ2VkLCAxIGluc2VydGlvbigr
KQoKZGlmZiAtLWdpdCBhL3NyYy90ZXN0L3JlY292ZXJ5L3QvMDM5X2VuZF9vZl93YWwucGwg
Yi9zcmMvdGVzdC9yZWNvdmVyeS90LzAzOV9lbmRfb2Zfd2FsLnBsCmluZGV4IDMxNjhkOTkx
ZmVlLi5mN2E2YTcyMmE3OCAxMDA2NDQKLS0tIGEvc3JjL3Rlc3QvcmVjb3ZlcnkvdC8wMzlf
ZW5kX29mX3dhbC5wbAorKysgYi9zcmMvdGVzdC9yZWNvdmVyeS90LzAzOV9lbmRfb2Zfd2Fs
LnBsCkBAIC0yODcsNiArMjg3LDcgQEAgJG5vZGUtPnN0b3AoJ2ltbWVkaWF0ZScpOwogbXkg
JGxvZ19zaXplID0gLXMgJG5vZGUtPmxvZ2ZpbGU7CiAkbm9kZS0+c3RhcnQ7CiBvayggJG5v
ZGUtPmxvZ19jb250YWlucygKKwkJImludmFsaWQgbWFnaWMgbnVtYmVyIDAwMDAgaW4gV0FM
IHNlZ21lbnR8IiAuCiAJCSJpbnZhbGlkIHJlY29yZCBsZW5ndGggYXQgLio6IGV4cGVjdGVk
IGF0IGxlYXN0IDI0LCBnb3QgMCIsICRsb2dfc2l6ZQogCSksCiAJInhsX3RvdF9sZW4gemVy
byIpOwotLSAKMi40My4wCgo=

--------------81Fv6q9XhyBxDfR8RT0cz20M--