削除後に再度作られた?-exitArchiveRecovery関数の後、いつRestoreArchivedFile関数が呼ばれるのか?まとめPostgreSQLのリカバリ周りにあったバグ修正について、発見から修正までに実際に行ったことを紹介しています。今回は原因究明編です。前回をまだ読んでいない方は前回の記事を先に読むことをおすすめします。前回おさらい前回はRECOVERYHISTORYファイルがなぜ作られるのか、そして作られた後どうなるのか?について調査しました。ソースコードを確認した所、RECOVERYHISTORYファイルは作られた後、KeepFileRestoredFromArchive関数にて名前が変えられたり、exitArchiveRecovery関数で削除(unlink)されていました。-exitArchiveRecovery関数をよく見ると、unlink関数が失敗した場合でもエラーを無視するようなコードになっています。:このことから、「unlink関数が何かしらの原因で失敗したためにRECOVERYHISTORYファイルが残ってしまったのではないか」という仮説が生まれます。仮説1の検証この仮説を検証するために実際にコードを変更して、unlink関数が成功したのか、失敗したのか、また、失敗したのであればなにがエラーの原因だったのかを見てましょう。src/backend/access/transam/xlog.cにあるexitArchiveRecovery関数を以下のように変更します。accidentallyここではいわゆるprintfデバッグをして、unlink関数が失敗した場合にエラーメッセージを表示するようにしています。PostgreSQLではelog関数を使ってprintfデバッグをすることが多いです。elog関数の第一引数にはエラーレベルを指定するのですが、私はいつも(面倒くさいので)WARNINGを指定しています。第二引数以降はprintfと同じです。上記の変更を加えたPostgreSQLをビルドし、インストールします(ビルド時にwarningが出るかもしれませんが無視します)。再度リカバリ手順を行うと以下のようなログが出力されます。directy)から、RECOVERYHISTORYファイルをunlinkをする時点(exitArchiveRecovery関数の時点)には当該ファイルは存在していない、ということがわかります。残念ながら仮説1(unlinkが失敗してファイルが残ってしまった説)は間違っていたということになります。削除後に再度作られた?-仮説1は間違っていましたが、検証したことによりexitArchiveRecovery関数が呼ばれる時にはRECOVERYHISTORYファイルが存在していないことがわかりました。このことから、「exitArchiveRecovery関数後にRECOVERYHISTORYファイルが作られたために消されずに残った」という次の仮説が生まれます。どこでRECOVERYHISTORYファイルは作られたのでしょうか?ソースコードから該当の箇所を探すことも可能ですが、この仮説が間違っていたら探しても見つからない可能性がありますし、今回は再現可能な事象でもありますので、コードを修正して実際に動かしてみながら探していきます。exitArchiveRecovery関数の後、いつRestoreArchivedFile関数が呼ばれるのか?前回の調査により、RECOVERYHISTORYファイルはRestoreArchivedFile関数で作成されています。今回の調査では、exitArchiveRecovery関数の後に呼ばれたRestoreArchivedFile関数でプロセスにデバッガでアタッチし、バックトレースを見ることで、いつどこでRECOVERYHISTORYファイルが作られたのかを確認する、という方針で調査します。一つ問題なのがRestoreArchivedFile関数はhistoryファイルだけでなく、リカバリに必要なWALのリストアも行う関数であるため、様々な所から呼ばることです。RestoreArchivedFile関数の先頭にsleepを入れてその間にアタッチする、としたかったのですが、そうすると何度もsleepしてしまい時間がかかってしまいそうなので、以下のように少し工夫してsleepするコードを追加します。0)かつ、アーカイブリカバリが終了している(!InArchiveRecovery)時のみsleepするようにしています。InArchiveRecoveryはrestoreArchivedFile関数でfalseに設定されます。これにより、今回調査したい状況でのみ20秒間sleepさせることができます。私はsleepする時はよくpg_usleep関数を使いますが、通常のsleep関数でも問題ありません。アタッチするプロセスのPIDを出力するためにMyProcPidを使っています。上記の変更を加えたPostgreSQLをビルドし、インストールします。再度リカバリ手順を行うと、追加したデバッグログの出力とともに動作がストップします。ストップしてる間に該当プロセスのバックトレースを見ます1。psコマンドで見るとわかるのですが、アタッチする対象のプロセスはstartupプロセスです。main.c:210(gdb)仮説2は正しかったようです!exitArchiveRecovery関数の直後に呼ばれるwriteTimeLineHistory関数からの呼び出しでRECOVERYHISTORYファイルが作成されていました(バックトレースの#3の所)。exitArchiveRecovery関数で不要(一時)ファイルの掃除がされていましたが、その後に作られたため最後まで残ってしまったのですね。reason);まとめ仮説→検証を繰り返すことでバグの原因をコードレベルで突き止める事ができました!ここまで来たら後は修正するだけです。修正する際には、コードの修正だけでなくいつこのバグが作り込まれたのか、、どのバージョンが影響を受けるのか、も見るようにしています。次回はもう少し問題となったコードを調べ、修正してみます。バックトレースを見るためにはconfigure時に--enable-debugを指定する必要があります。詳細はこちらをご参照ください。@masahiko_sawada。