Content-Type: multipart/mixed; boundary="------------IM0GK5gxZ6OgcoB1IQ6own0z"
Message-ID: <f7c8204e-ba32-4bf0-aef3-f0f9e55a3347@arenadata.io>
Date: Fri, 17 Jan 2025 11:05:53 +1000
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Content-Language: ru
To: pgsql-hackers@lists.postgresql.org
From: Roman Eskin <r.eskin@arenadata.io>
Subject: Timeline issue if StartupXLOG() is interrupted right before
 end-of-recovery record is done
Archived-At: <https://www.postgresql.org/message-id/f7c8204e-ba32-4bf0-aef3-f0f9e55a3347%40arenadata.io>
Precedence: bulk

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

Hello pgsql-hackers,

It appears to exist an issue with timeline switching in archive
recovery mode if the startup process is interrupted by some external
reason (for ex. system power loss) in a specific tight time window
(after a new history file is created but before end-of-recovery record
is done). If this happens, and the Postgres instance is launched
again, it carries out the common crash recovery, starts successfully
to 'in production' state, but continues the previous timeline. Thus,
we are having inconsistent WAL state, where we are writing WAL segment
files to old timeline and having presented new orphaned timeline in
the history file.

This issue can reveal itself in streaming replication scenario, for
ex.:
1. Assume we have instance_1 (Master) and instance_2 (Replica);
2. instance_1 (Master) fails for any reason, instance_2 (Replica)
starts to promote. But while instance_2 is still in `StartupXLOG()`
somewhere between `writeTimeLineHistory()` and
`CreateEndOfRecoveryRecord()`, we are getting, for example, power
loss on instance_2 server.
3. Once instance_2 server is up again, instance_2 is restarted. The
problem with timeline already exists here, but very likely to be
unnoticed, as instance_2 (now Master) is accepting connections and
working.
4. Bring back instance_1 as Replica.
5. Switch back instance_1 and instance_2 to the original
configuration. And here, when we try to start instance_2 as Replica,
we'll get a FATAL:
"FATAL: requested timeline 2 is not a child of this server's history
DETAIL: Latest checkpoint is at 0/303FF90 on timeline 1, but in the
history of the requested timeline, the server forked off from that
timeline at 0/3023538."

I agree that one have to be very unlucky to get into such situation
with 2 consequent failures and to hit the specific time window, but if
this happens, it will look quite severe and hard to debug. We faced
this situation on our synthetic tests.

To reproduce the issue on latest code from Postgres master branch in a
stable manner, I used the attached
'test-code-for-timeline-issue.patch'. It postpones execution in
`StartupXLOG()` if we need to hit the requested time window. Detailed
steps to reproduce I've used with the patch are in the attached file
'steps - NG scenario.txt'.

Possible way to fix this issue, that we now consider, is to postpone
the removal of signal files ("recovery.signal" and "standby.signal")
until the end-of-recovery record is done, and thus retry interrupted
promotion in case previous one failed. Looks like, the only
insignificant negative outcome for this approach is possible
assignment of one more timeline identity. But we would like to get
more feedback from the community. Do you foresee any possible
drawbacks for this approach? Please advise.

Many thanks in advance!

P.S. The topic above is a bit similar to this old one -
https://www.postgresql.org/message-id/flat/CABUevEz09XY2EevA2dLjPCY-C5UO4Hq%3DXxmXLmF6ipNFecbShQ%40mail.gmail.com.

Best regards,
Roman Eskin
--------------IM0GK5gxZ6OgcoB1IQ6own0z
Content-Type: text/plain; charset=UTF-8; name="steps - NG scenario.txt"
Content-Disposition: attachment; filename="steps - NG scenario.txt"
Content-Transfer-Encoding: base64

VEVTVF9QR19QT1JUX01BU1RFUj01NDMzDQpURVNUX1BHX1BPUlRfUkVQTElDQT01NDM0DQoN
ClRFU1RfUEdfRElSX01BU1RFUj1+L3Bvc3RncmVzX2RhdGFfbWFzdGVyDQpURVNUX1BHX0RJ
Ul9SRVBMSUNBPX4vcG9zdGdyZXNfZGF0YV9yZXBsaWNhDQoNCg0KIyBTZXR1cCBtYXN0ZXIN
Cm1rZGlyICRURVNUX1BHX0RJUl9NQVNURVINCg0KcGdfY3RsIC1EICRURVNUX1BHX0RJUl9N
QVNURVIgaW5pdGRiDQoNCnNlZCAtaSAicy8jbGlzdGVuX2FkZHJlc3NlcyA9ICdsb2NhbGhv
c3QnL2xpc3Rlbl9hZGRyZXNzZXMgPSAnKicvZyIgJFRFU1RfUEdfRElSX01BU1RFUi9wb3N0
Z3Jlc3FsLmNvbmYNCnNlZCAtaSAicy8jcG9ydCA9IDU0MzIvcG9ydCA9ICRURVNUX1BHX1BP
UlRfTUFTVEVSL2ciICRURVNUX1BHX0RJUl9NQVNURVIvcG9zdGdyZXNxbC5jb25mDQoNCnBn
X2N0bCAtRCAkVEVTVF9QR19ESVJfTUFTVEVSIC1sIGxvZ2ZpbGUgc3RhcnQNCg0KIyBTZXR1
cCByZXBsaWNhDQpwZ19iYXNlYmFja3VwIC1oIGxvY2FsaG9zdCAtLWNoZWNrcG9pbnQ9ZmFz
dCAtRCAkVEVTVF9QR19ESVJfUkVQTElDQSAtUiAtWCBzdHJlYW0gLS1wb3J0PSRURVNUX1BH
X1BPUlRfTUFTVEVSDQpzZWQgLWkgInMvI2xpc3Rlbl9hZGRyZXNzZXMgPSAnbG9jYWxob3N0
Jy9saXN0ZW5fYWRkcmVzc2VzID0gJyonL2ciICRURVNUX1BHX0RJUl9SRVBMSUNBL3Bvc3Rn
cmVzcWwuY29uZg0Kc2VkIC1pICJzL3BvcnQgPSAkVEVTVF9QR19QT1JUX01BU1RFUi9wb3J0
ID0gJFRFU1RfUEdfUE9SVF9SRVBMSUNBL2ciICRURVNUX1BHX0RJUl9SRVBMSUNBL3Bvc3Rn
cmVzcWwuY29uZg0KDQpwZ19jdGwgLUQgJFRFU1RfUEdfRElSX1JFUExJQ0EgLWwgbG9nZmls
ZV9yZXBsaWNhIHN0YXJ0DQoNCiMgQ2hlY2sgcmVwbGljYXRpb24gaXMgd29ya2luZw0KcHNx
bCBwb3N0Z3JlcyAtLXBvcnQ9JFRFU1RfUEdfUE9SVF9NQVNURVIgLWMgIg0KY3JlYXRlIHRh
YmxlIHQgKA0KICBhIGludGVnZXIsDQogIGIgdGV4dCwNCiAgZCB0aW1lc3RhbXAgd2l0aG91
dCB0aW1lIHpvbmUNCik7DQppbnNlcnQgaW50byB0IHNlbGVjdCBpLCAndGVzdC1tYXN0ZXIt
Mi1yZXBsaWNhJ3x8aSAsIG5vdygpIGZyb20gZ2VuZXJhdGVfc2VyaWVzKDEsIDUpaTsNCiIN
CnNsZWVwIDINCnBzcWwgcG9zdGdyZXMgLS1wb3J0PSRURVNUX1BHX1BPUlRfUkVQTElDQSAt
YyAic2VsZWN0ICogZnJvbSB0OyI7DQoNCiMgU2h1dGRvd24gbWFzdGVyIGFuZCBzd2l0Y2gg
dG8gcmVwbGljYQ0KcGdfY3RsIC1EICRURVNUX1BHX0RJUl9NQVNURVIgc3RvcA0KDQojIGVu
YWJsZSB0ZXN0IGNoYW5nZXMgdGhhdCB3aWxsIHBvc3Rwb25lIENyZWF0ZUVuZE9mUmVjb3Zl
cnlSZWNvcmQoKQ0KdG91Y2ggJFRFU1RfUEdfRElSX1JFUExJQ0EvZGVsYXlfcmVjb3Zlcnku
c2lnbmFsDQoNCnBzcWwgcG9zdGdyZXMgLS1wb3J0PSRURVNUX1BHX1BPUlRfUkVQTElDQSAt
YyAiU0VMRUNUIHBnX3Byb21vdGUoKTsiICYNCg0KIyBTaHV0ZG93biBpbW1lZGlhdGVseSBQ
b3N0Z3JlcyAoaW4gcmVhbCBsaWZlIHRoYXQgY291bGQgYmUgYW4gYWNjaWRlbnQgcG93ZXIg
bG9zcywgb3IgYW55IG90aGVyIHN5c3RlbSBsZXZlbCBwcm9ibGVtLi4uKQ0Kc2xlZXAgNSAj
IHNsZWVwIGEgd2hpbGUgdG8gZW5zdXJlIHRoYXQgaGlzdG9yeSBmaWxlIHdhcyBjcmVhdGVk
DQpwZ19jdGwgLUQgJFRFU1RfUEdfRElSX1JFUExJQ0Egc3RvcCAtbSBpDQpzbGVlcCA1DQoj
IGNsZWFudXAgLSB3ZSBkbyBub3QgbmVlZCB0aGUgZmlsZSBhbnltb3JlDQpybSAkVEVTVF9Q
R19ESVJfUkVQTElDQS9kZWxheV9yZWNvdmVyeS5zaWduYWwNCiMgc3RhcnQgcmVwbGljYSBh
Z2Fpbg0KcGdfY3RsIC1EICRURVNUX1BHX0RJUl9SRVBMSUNBICAtbCBsb2dmaWxlX3JlcGxp
Y2Egc3RhcnQNCiMgYWZ0ZXIgdGhpcyBwb2ludCByZXBsaWNhIGlzIHN0YXJ0ZWQsIGFuZCB3
b3JraW5nLCBidXQgdGhlIHRpbWVsaW5lIGlzIHN0aWxsIDEgISEhDQojIGl0IGNhbiBiZSBj
aGVja2VkIHdpdGggYHBnX2NvbnRyb2xkYXRhICRURVNUX1BHX0RJUl9SRVBMSUNBYA0KIyBh
bmQgd2Ugd2lsbCBnZXQgcHJvYmxlbXMgbGF0ZXIgb25jZSB3ZSBzd2l0Y2ggdGhlIHJlcGxp
Y2EgYmFjayB0byBpdHMgb3JpZ2luYWwgcm9sZSAocmVmZXIgdG8gc3RlcHMgYmVsb3cpLg0K
DQojIEJyaW5nIGJhY2sgbWFzdGVyIGFzIHJlcGxpY2ENCnRvdWNoICRURVNUX1BHX0RJUl9N
QVNURVIvc3RhbmRieS5zaWduYWwNCnNlZCAtaSAicy8jcHJpbWFyeV9jb25uaW5mbyA9ICcn
L3ByaW1hcnlfY29ubmluZm8gPSAnaG9zdD1sb2NhbGhvc3QgcG9ydD0kVEVTVF9QR19QT1JU
X1JFUExJQ0EnL2ciICRURVNUX1BHX0RJUl9NQVNURVIvcG9zdGdyZXNxbC5jb25mDQpwZ19j
dGwgLUQgJFRFU1RfUEdfRElSX01BU1RFUiAtbCBsb2dmaWxlIHN0YXJ0DQoNCiMgQ2hlY2sg
cmVwbGljYXRpb24gaXMgd29ya2luZw0KcHNxbCBwb3N0Z3JlcyAtLXBvcnQ9JFRFU1RfUEdf
UE9SVF9SRVBMSUNBIC1jICINCmNyZWF0ZSB0YWJsZSB0MiAoDQogIGEgaW50ZWdlciwNCiAg
YiB0ZXh0LA0KICBkIHRpbWVzdGFtcCB3aXRob3V0IHRpbWUgem9uZQ0KKTsNCmluc2VydCBp
bnRvIHQyIHNlbGVjdCBpLCAndGVzdC1yZXBsaWNhLTItbWFzdGVyJ3x8aSAsIG5vdygpIGZy
b20gZ2VuZXJhdGVfc2VyaWVzKDEsIDUpaTsNCiINCnNsZWVwIDINCnBzcWwgcG9zdGdyZXMg
LS1wb3J0PSRURVNUX1BHX1BPUlRfTUFTVEVSIC1jICJzZWxlY3QgKiBmcm9tIHQyOyI7DQoN
CiMgU3dpdGNoIGJhY2sNCnBnX2N0bCAtRCAkVEVTVF9QR19ESVJfUkVQTElDQSBzdG9wDQoN
CnBzcWwgcG9zdGdyZXMgLS1wb3J0PSRURVNUX1BHX1BPUlRfTUFTVEVSIC1jICJTRUxFQ1Qg
cGdfcHJvbW90ZSgpOyINCg0KdG91Y2ggJFRFU1RfUEdfRElSX1JFUExJQ0Evc3RhbmRieS5z
aWduYWwNCnBnX2N0bCAtRCAkVEVTVF9QR19ESVJfUkVQTElDQSAtbCBsb2dmaWxlX3JlcGxp
Y2Egc3RhcnQNCg0KIyBhdHRlbXB0IHRvIHN0YXJ0IHJlcGxpY2EgaGVyZSB3aWxsIHJlc3Vs
dCBpbjoNCiMgCSdwZ19jdGw6IGNvdWxkIG5vdCBzdGFydCBzZXJ2ZXInDQojIAknRXhhbWlu
ZSB0aGUgbG9nIG91dHB1dC4nDQojIGFuZCBpbiB0aGUgbG9nOg0KIwkyMDI1LTAxLTE2IDE3
OjMwOjI3LjE3NCArMTAgWzQ4MDZdIEZBVEFMOiAgcmVxdWVzdGVkIHRpbWVsaW5lIDIgaXMg
bm90IGEgY2hpbGQgb2YgdGhpcyBzZXJ2ZXIncyBoaXN0b3J5DQojCTIwMjUtMDEtMTYgMTc6
MzA6MjcuMTc0ICsxMCBbNDgwNl0gREVUQUlMOiAgTGF0ZXN0IGNoZWNrcG9pbnQgaXMgYXQg
MC8zMDNGRjkwIG9uIHRpbWVsaW5lIDEsIGJ1dCBpbiB0aGUgaGlzdG9yeSBvZiB0aGUgcmVx
dWVzdGVkIHRpbWVsaW5lLCB0aGUgc2VydmVyIGZvcmtlZCBvZmYgZnJvbSB0aGF0IHRpbWVs
aW5lIGF0IDAvMzAyMzUzOC4NCiMNCg==
--------------IM0GK5gxZ6OgcoB1IQ6own0z
Content-Type: text/plain; charset=UTF-8;
 name="test-code-for-timeline-issue.patch"
Content-Disposition: attachment; filename="test-code-for-timeline-issue.patch"
Content-Transfer-Encoding: base64

ZGlmZiAtLWdpdCBhL3NyYy9iYWNrZW5kL2FjY2Vzcy90cmFuc2FtL3hsb2cuYyBiL3NyYy9i
YWNrZW5kL2FjY2Vzcy90cmFuc2FtL3hsb2cuYwppbmRleCBiZjNkYmRhOTAxLi5iZGZjOTJj
ZDZlIDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC9hY2Nlc3MvdHJhbnNhbS94bG9nLmMKKysr
IGIvc3JjL2JhY2tlbmQvYWNjZXNzL3RyYW5zYW0veGxvZy5jCkBAIC02MTI2LDYgKzYxMjYs
MTkgQEAgU3RhcnR1cFhMT0codm9pZCkKIAlJbnNlcnQtPmZ1bGxQYWdlV3JpdGVzID0gbGFz
dEZ1bGxQYWdlV3JpdGVzOwogCVVwZGF0ZUZ1bGxQYWdlV3JpdGVzKCk7CiAKKwkvKgorCSAq
IENvZGUgYmVsb3cgaXMgZm9yIHRlc3QgcHVycG9zZXMgb25seSB0byByZXZlYWwgcG9zc2li
bGUgdGltZWxpbmUgaXNzdWUuCisJICovCisJeworCQlzdHJ1Y3Qgc3RhdCBzdDsKKworCQll
bG9nKExPRywgIlN0YXJ0IGRlbGF5IGluIFN0YXJ0dXBYTE9HKCkiKTsKKworCQl3aGlsZSAo
c3RhdCgiZGVsYXlfcmVjb3Zlcnkuc2lnbmFsIiwgJnN0KSA9PSAwKQorCQkJcGdfdXNsZWVw
KDEwMDAwTCk7IC8qIHNsZWVwIGZvciAxMCBtcyovCisKKwkJZWxvZyhMT0csICJTdG9wIGRl
bGF5IGluIFN0YXJ0dXBYTE9HKCkiKTsKKwl9CiAJLyoKIAkgKiBFbWl0IGNoZWNrcG9pbnQg
b3IgZW5kLW9mLXJlY292ZXJ5IHJlY29yZCBpbiBYTE9HLCBpZiByZXF1aXJlZC4KIAkgKi8K


--------------IM0GK5gxZ6OgcoB1IQ6own0z--