PostgreSQLのリカバリ周りのバグを修正してみた - 原因究明編 -
PostgreSQLのリカバリ周りにあったバグ修正について、発見から修正までに実際に行ったことを紹介しています。今回は原因究明編です。前回をまだ読んでいない方は前回の記事を先に読むことをおすすめします。
前回おさらい
前回はRECOVERYHISTORYファイルがなぜ作られるのか、そして作られた後どうなるのか？について調査しました。
そしてソースコードを確認した所、RECOVERYHISTORYファイルは作られた後、KeepFileRestoredFromArchive関数にて名前が変えられたり、exitArchiveRecovery関数で削除(unlink)されていました。
仮説１ - 削除失敗? -
exitArchiveRecovery関数をよく見ると、unlink関数が失敗した場合でもエラーを無視するようなコードになっています。
:
/* Get rid of any remaining recovered timeline-history file, too */
snprintf(recoveryPath, MAXPGPATH, XLOGDIR "/RECOVERYHISTORY");
unlink(recoveryPath); /* ignore any error */
:
このことから、「unlink関数が何かしらの原因で失敗したためにRECOVERYHISTORYファイルが残ってしまったのではないか」という仮説が生まれます。
仮説1の検証
この仮説を検証するために実際にコードを変更して、unlink関数が成功したのか、失敗したのか、また、失敗したのであればなにがエラーの原因だったのかを見てましょう。
src/backend/access/transam/xlog.cにあるexitArchiveRecovery関数を以下のように変更します。
diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c
index 61ba6b852e..24fd8ea689 100644
--- a/src/backend/access/transam/xlog.c
+++ b/src/backend/access/transam/xlog.c
@@ -5550,7 +5550,10 @@ exitArchiveRecovery(TimeLineID endTLI, XLogRecPtr endOfLog)
/* Get rid of any remaining recovered timeline-history file, too */
snprintf(recoveryPath, MAXPGPATH, XLOGDIR "/RECOVERYHISTORY");
- unlink(recoveryPath); /* ignore any error */
+ int r;
+ r = unlink(recoveryPath); /* ignore any error */
+ if (r < 0)
+ elog(WARNING, "unlink error!! %m");
/*
* Remove the signal files out of the way, so that we don't accidentally
ここではいわゆるprintfデバッグをして、unlink関数が失敗した場合にエラーメッセージを表示するようにしています。PostgreSQLではelog関数を使ってprintfデバッグをすることが多いです。elog関数の第一引数にはエラーレベルを指定するのですが、私はいつも（面倒くさいので）WARNINGを指定しています。第二引数以降はprintfと同じです。
上記の変更を加えたPostgreSQLをビルドし、インストールします(ビルド時にwarningが出るかもしれませんが無視します)。そして、再度リカバリ手順を行うと以下のようなログが出力されます。
WARNING: unlink error!! No such file or directory
上記のエラーメッセージ(No such file or directy)から、RECOVERYHISTORYファイルをunlinkをする時点(exitArchiveRecovery関数の時点)には当該ファイルは存在していない、ということがわかります。つまり、残念ながら仮説1（unlinkが失敗してファイルが残ってしまった説）は間違っていたということになります。
仮説2 - 削除後に再度作られた？-
仮説1は間違っていましたが、検証したことによりexitArchiveRecovery関数が呼ばれる時にはRECOVERYHISTORYファイルが存在していないことがわかりました。このことから、「exitArchiveRecovery関数後にRECOVERYHISTORYファイルが作られたために消されずに残った」という次の仮説が生まれます。
では、どこでRECOVERYHISTORYファイルは作られたのでしょうか？ソースコードから該当の箇所を探すことも可能ですが、この仮説が間違っていたら探しても見つからない可能性がありますし、今回は再現可能な事象でもありますので、コードを修正して実際に動かしてみながら探していきます。
exitArchiveRecovery関数の後、いつRestoreArchivedFile関数が呼ばれるのか？
前回の調査により、RECOVERYHISTORYファイルはRestoreArchivedFile関数で作成されています。今回の調査では、exitArchiveRecovery関数の後に呼ばれたRestoreArchivedFile関数でプロセスにデバッガでアタッチし、バックトレースを見ることで、いつどこでRECOVERYHISTORYファイルが作られたのかを確認する、という方針で調査します。
ただ一つ問題なのがRestoreArchivedFile関数はhistoryファイルだけでなく、リカバリに必要なWALのリストアも行う関数であるため、様々な所から呼ばることです。
RestoreArchivedFile関数の先頭にsleepを入れてその間にアタッチする、としたかったのですが、そうすると何度もsleepしてしまい時間がかかってしまいそうなので、以下のように少し工夫してsleepするコードを追加します。
diff --git a/src/backend/access/transam/xlogarchive.c b/src/backend/access/transam/xlogarchive.c
index 9a21f006d1..ad28f4cb2a 100644
--- a/src/backend/access/transam/xlogarchive.c
+++ b/src/backend/access/transam/xlogarchive.c
@@ -213,6 +213,12 @@ RestoreArchivedFile(char *path, const char *xlogfname,
if (rc == 0)
{
+ if (!InArchiveRecovery)
+ {
+ elog(WARNING, "restoring %s!! %d", xlogfname, MyProcPid);
+ pg_usleep(20 * 1000000L);
+ }
+
/*
* command apparently succeeded, but let's make sure the file is
* really there now and has the correct size.
リストアが成功した場合(rc == 0)かつ、アーカイブリカバリが終了している(!InArchiveRecovery)時のみsleepするようにしています。InArchiveRecoveryはrestoreArchivedFile関数でfalseに設定されます。これにより、今回調査したい状況でのみ20秒間sleepさせることができます。
私はsleepする時はよくpg_usleep関数を使いますが、通常のsleep関数でも問題ありません。アタッチするプロセスのPIDを出力するためにMyProcPidを使っています。
上記の変更を加えたPostgreSQLをビルドし、インストールします。そして、再度リカバリ手順を行うと、追加したデバッグログの出力とともに動作がストップします。そして、ストップしてる間に該当プロセスのバックトレースを見ます1。psコマンドで見るとわかるのですが、アタッチする対象のプロセスはstartupプロセスです。
:
WARNING: restoring 00000002.history!! 20097
$ gdb -p 20097
GNU gdb (GDB) 8.3
Copyright (C) 2019 Free Software Foundation, Inc.
:
(gdb) bt
#0 0x00007f5d2c590e0b in select () from /usr/lib/libc.so.6
#1 0x00005634aea20918 in pg_usleep (microsec=20000000) at pgsleep.c:56
#2 0x00005634ae44b55e in RestoreArchivedFile (path=0x7ffcf05e52c0 "", xlogfname=0x7ffcf05e5280 "00000002.history",
recovername=0x5634aea53d1d "RECOVERYHISTORY", expectedSize=0, cleanupEnabled=false) at xlogarchive.c:219
#3 0x00005634ae42881f in writeTimeLineHistory (newTLI=3, parentTLI=2, switchpoint=83886080,
reason=0x7ffcf05e81c0 "no recovery target specified") at timeline.c:322
#4 0x00005634ae442337 in StartupXLOG () at xlog.c:7493
#5 0x00005634ae76dcc5 in StartupProcessMain () at startup.c:207
#6 0x00005634ae458b67 in AuxiliaryProcessMain (argc=2, argv=0x7ffcf05e8690) at bootstrap.c:451
#7 0x00005634ae76cac3 in StartChildProcess (type=StartupProcess) at postmaster.c:5414
#8 0x00005634ae7672a1 in PostmasterMain (argc=3, argv=0x5634b03a19a0) at postmaster.c:1383
#9 0x00005634ae66e472 in main (argc=3, argv=0x5634b03a19a0) at main.c:210
(gdb)
仮説2は正しかったようです！exitArchiveRecovery関数の直後に呼ばれるwriteTimeLineHistory関数からの呼び出しでRECOVERYHISTORYファイルが作成されていました(バックトレースの#3の所)。exitArchiveRecovery関数で不要（一時）ファイルの掃除がされていましたが、その後に作られたため最後まで残ってしまったのですね。
/*
* We are now done reading the old WAL. Turn off archive fetching if
* it was active, and make a writable copy of the last WAL segment.
* (Note that we also have a copy of the last block of the old WAL in
* readBuf; we will use that below.)
*/
exitArchiveRecovery(EndOfLogTLI, EndOfLog);
/*
* Write the timeline history file, and have it archived. After this
* point (or rather, as soon as the file is archived), the timeline
* will appear as "taken" in the WAL archive and to any standby
* servers. If we crash before actually switching to the new
* timeline, standby servers will nevertheless think that we switched
* to the new timeline, and will try to connect to the new timeline.
* To minimize the window for that, try to do as little as possible
* between here and writing the end-of-recovery record.
*/
writeTimeLineHistory(ThisTimeLineID, recoveryTargetTLI,
EndRecPtr, reason);
まとめ
仮説→検証を繰り返すことでバグの原因をコードレベルで突き止める事ができました！ここまで来たら後は修正するだけです。修正する際には、コードの修正だけでなくいつこのバグが作り込まれたのか、、どのバージョンが影響を受けるのか、も見るようにしています。
次回はもう少し問題となったコードを調べ、修正してみます。