この記事は、animateLAB Advent Calendar 2015 13日目の記事です。
こんばんは、kariaです。きょうは昨日の「誕生日なのでMySQLの話をする（その1）」の続きを書こうと思います。
これまでのあらすじ
MySQLのデータ（本番環境）を過去のダンプファイルで上書きされちゃった！？どーしよ！？
復旧までの道のり
我々の手元に残されたデータは以下の2つです。
- 早朝のデータ移行時に使用したダンプファイル
- MySQLのデータディレクトリ一式（←夕方に上書きされちゃったやつ）
上書きされちゃったやつはもはやどうしようもないし、早朝時点のダンプファイルを使って再構築し直してその日中帯のトランザクションは諦めるか、という案もありました。とはいえ、「諦めって言われてもその間のトランザクションは具体的にどうするんだ、ログから全部洗うか？」という事になりますし、「無くなりました、ゴメンナサイ」ということにはしたくないものです。
ここでMySQLのとあるオプションを思い出してみましょう。
log_bin = /var/lib/mysql/mysql-bin.log expire_logs_days = 0
これはバイナリログの保存先ディレクトリと、どれぐらいの期間でexpire（削除）するかというオプションです。バイナリログは通常MySQLのレプリケーションを実現するために使用されます（マスターDBが差分をバイナリログファイルとして出力して、スレーブDBが取り込んで反映する）。MySQLのデータディレクトリが肥大化するのを防ぐため、バイナリログをexpireされるまでの日数を小さく制限するというTIPSをよく見かけます。
が、MySQL リファレンスマニュアルにあるバイナリログの項目を読むと以下のように記載されています。
バイナリロギングを有効にしてサーバーを実行すると、パフォーマンスがいくらか低下します。ただし、レプリケーションをセットアップでき、リストア操作に対応できるというバイナリログの利点は、一般的にこのパフォーマンスの減少よりも重要です。
そう、バイナリログはリストア操作のためのバックアップとしても機能します。ということは
早朝のデータ移行時に使用したダンプファイル ＋ 早朝～夕方（サイト閉鎖直前）までのbinlog ⇒ サイト閉鎖直前までの完全なデータが帰ってくる！！！
やったー！！ということで夜を徹しての復旧作業が始まりました。
具体的な復旧手順
バイナリログからのリカバリですが、具体的には、mysqlbinlogというユーティリティーを使用します。使用方法は以下の通り。
# mysqlbinlog (binlog_filename)
※手元の環境で試したところ、一般ユーザで実行するとPermission deniedと言われてしまったのでroot権限で実行しています。
すると、以下のようにトランザクションの中身が平文で表示されます。
# at 684657
#151213 23:25:52 server id 1 end_log_pos 684657 CRC32 0x3e4f5587 Intvar
SET INSERT_ID=1268556/*!*/;
#151213 23:25:52 server id 1 end_log_pos 684989 CRC32 0x25bc1ac9 Query thread_id=36 exec_time=0 error_code=0
SET TIMESTAMP=1450016752/*!*/;
insert into log (is_notice,nick_id,channel_id,log,created_on,updated_on) values ('0','42','1','うんっ！行くよっ！いつも、今が、最高でしょ！れでぃーごー！ 14(aije) (from Alice Cartelet)',now(),now())
/*!*/;
平文で表示されますので、そのままパイプでmysqlコマンドに食わせても良いですし、ファイルに出力したりgrepしたりしても構いません。なお上記サンプルは、tiarraMetroに付属するLog::DBIというtiarraのmoduleを利用して、私がTwitterに以下のような発言をした際に発行されたinsert文です。
うんっ！行くよっ！いつも、今が、最高でしょ！れでぃーごー！
— karia(かーりあ)@1日目西ら03 (@karia) 2015, 12月 13このコマンドがあれば実質的にMySQLへ発行された更新系のクエリを全て追うことができ、非常に便利なコマンドですので覚えておきましょう。
さて、これを踏まえて具体的な復旧手順は以下のようになります。
- 早朝時点のデータダンプを改めてインポートする
- mysqlbinlogユーリティティを使用して早朝時点～夕方（サイト閉鎖時点）までのトランザクションをバイナリログから取りだす
- インポートしたdatabaseに上記トランザクションを適用する
かんたん3ステップ！というように見えますがそうはいきません。
2ステップ目で「早朝時点～夕方（サイト閉鎖時点）までのトランザクションをバイナリログから取りだし」と書いてますが、MySQLのバイナリログはmysql-bin.000001といったように無機質な連番でファイルが作成されていくので、一見してどこからどこまでが適用対象のトランザクションなのかがわかりません。ただ、一定のファイルサイズを超えると次の番号のファイルへ出力されるようになるのと、上記で示したようにトランザクション実行日時がコメントアウトされた形で示されていますので、ファイルのタイムスタンプとトランザクション実行日時を手がかりに当該のトランザクションを全て洗い出します。これ自体は手作業（目視）で行うことになりました。
これらの作業をたまたま空いていた別環境を用意して検証し、トランザクション適用で1件もエラーが出ないこと・夕方時点までのトランザクションが実際に入っていることを確認した上で、本番環境で実施・およびアプリケーションの動作確認・メンテナンスモード解除といった流れとなりました。また、これら作業の中で「default charset=utf8つけた？？？」と親の敵のように何度も確認したことも忘れられない思い出です。
データ量にもよりますがこれらの作業にはそれなりの時間がかかります。確かトランザクションの適用中のことだったと思うのですが、日付が変わったあとどこかで「昨日誕生日だったんですよね……」と漏らしたところ、当時の上司がケーキを買ってきてくれるという出来事がありました。バイナリログから復旧させるというアイデア自体も私ではなく別の上司のアイデアですし、1人できる復旧作業ではありませんでしたので当時の同僚や上司には本当に感謝しています。
ということで、私の中で「誕生日といえばMySQL」という謎のワードが生まれたきっかけになった出来事をご紹介しました。mysqlbinlogコマンドは大変便利ですので是非活用しましょう。また、log_binオプションはデフォルトだと無効になっているので、レプリケーションを行わない環境であっても有効にしておくと良いでしょう。
