2024年1月1日は、ひどい一日になりました。
16時過ぎ、スマートフォンやタブレットにインストールしている地震アプリがアラートを発し始め、能登半島で大規模地震が発生したことに気づきました。我が家は震源から十分離れているため全く揺れませんでしたが、TVニュースと動画サイトの情報を見ていたら、同じPC画面上に表示させているターミナルエミュレータの様子が何かおかしい。(余談ですが、複数端末に防災アプリを入れていたら、今回のような連続大地震の時は、アラート鳴りっぱなしで、地震アラートの遅延なのか、新規地震なのかわからなくなることに気づきました。津波警報も入ってくるし、特に、自分がいる場所が揺れていない場合、大変な状況とだけわかるけど、気付くべき重要情報が何なのか見えなくなる。ゆれくるコールは、震度震源地図へのアクセス集中か、真っ白な地図に数字だけが表示されてた。すべての端末に防災アプリいれて、プッシュ通知を有効にするのは良くないかも。)
データベースサーバーと接続している端末のセッションが切れている。
当サイトのページをめくろうとすると、データベースと接続できない「データベース接続確立エラー」表示となり、コンテンツを表示できない状況になっていました。
データベースサーバーは、昨年、立ち上げた FreeBSD/arm 13.2 のRPI2 + USB HDDで動いているのですが、ネットワークからログインしようとしても接続できず、コンソールは真っ暗。
何か起きているのか状況不明で、できることは再起動のみ。
とりあえず、RPI2だけ電源Off→Onしたものの、HDDが見えないのか OS起動できず。HDDも再起動するとRPI2から FreeBSD/arm が起動し、ログインプロンプトが出てくるもののログインできず。そのうちコンソール画面に、
(da0:umass-sim0:0:0:0): READ(10). CDB: 28 00 02 1f c0 40 00 00 40 00
(da0:umass-sim0:0:0:0): CAM status: CCB request completed with an error
(da0:umass-sim0:0:0:0): Retrying command, 3 more tries remain
て、表示が現れました。
げっ、HDD クラッシュだ!
このメッセージはHDDのハードウェアトラブル。過去の経験から、このメッセージが出始めたらHDD交換準備を行わないとHDDが壊れる直前ってこと。普通は、デイリーレポートにこのメッセージが載るので、その後対応するのですけど、エラーが出て、即、クラッシュというケースも発生します。今回はこっちのケースの模様。
OSさえ起動してくれれば、修復できる可能性がありますが、1回目の再起動ではそこまでたどり着けなかった。特に FreeBSD/arm はブートメニューが FreeBSD/x86, amd64 とは異なるのがやっかい。
問題は、HDD上のどの部分がクラッシュしているのか?ということ。OSが落ちたことから、OSやライブラリファイルがある部分がクラッシュした可能性が高い。
RPI2とHDDのOff・On を繰り返しログインでまで進めるようになりましたが、自動でfsckが動いているらしく、不良セクターに差し掛かると、上記エラーとなって、運が悪いとOSが止まるみたい。
やるべきことは、
- mysqldump コマンドでデータベース全体をエクスポートして、別ファイルシステムにコピーする。または、
- /var/db/mysql ディレクトリ以下を丸々固めて別のファイルシステムにコピーする。
のどちらか。できれば1の方でバックアップを行いたいところでしたが、なぜか mysql が起動しない。というか、起動しても、すぐ落ちるので、2の mysql ディレクトリを丸々バックアップすることにしました。
と、言っても、RPI2 で作業しても、しばらくすると不良セクターを修復しようとしてOSが落ちるので、SDメモリで動いているバックアップデータベースサーバーに、外部ドライブとして接続して /mnt にマウントした後、データベースを吸い出すことにしようとしたところ、またまた問題発生。
バックアップデーターベースサーバーのファイルシステムの方も、私が気づかないところでダメージを受けていて(おそらく、テーブルタップのブレーカーが落ちた時に巻き込まれたせいでしょう)HDD上のファイルシステムを修復できたとしても、ファイルを吸い出せないことが判明。しかも、fsck の自動修復では修復できないレベル。SDメモリファイルシステムのことは、データベース吸出し後に考えるとして、別に動いている RPI4 FreeBSD/aarch で作業を続けることにしました。RPI4上のFreeBSD だと、HDDファイルシステムは追加ファイルシステム扱いなので、欠陥セクターをアクセスしてもOSは落ちないはず。(やってみたら不良セクターに遭遇した場合、低確率でOSが落ちた。)
稼働中のRPI4にデータベースシステムのHDDを接続して、fsck で修復。その後、/mnt にマウントして、
cd /var/db find mysql | cpio -ov > /home/mysql_bak.cpio
でバックアップを始めたものの、
./#innodb_redo/#ib_redo50 ./#innodb_redo/#ib_redo51 ./#innodb_redo/#ib_redo52 ./#innodb_redo/#ib_redo53 ./#innodb_redo/#ib_redo54 ./#innodb_redo/#ib_redo55_tmp cpio: Can't lstat ./#innodb_redo/#ib_redo56_tmp cpio: Can't lstat ./#innodb_redo/#ib_redo57_tmp cpio: Can't lstat ./#innodb_redo/#ib_redo58_tmp
特定のファイルをコピーする段階で引っかかってしまう。#ib_redo54 あたりを吸い出している時点で、ファイルアクセスが止まってしまい、Can’t lstat となり、その後は、(青文字は、HDD接続時のメッセージ)
da1 at umass-sim1 bus 1 scbus1 target 0 lun 0
da1: Fixed Direct Access SCSI device
da1: 40.000MB/s transfers
da1: 238475MB (488397168 512 byte sectors)
da1: quirks=0x2
(da1:umass-sim1:1:0:0): READ(10). CDB: 28 00 02 1f c0 00 00 00 80 00
(da1:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(da1:umass-sim1:1:0:0): Retrying command, 3 more tries remain
(da1:umass-sim1:1:0:0): READ(10). CDB: 28 00 02 1f c0 00 00 00 80 00
(da1:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(da1:umass-sim1:1:0:0): Retrying command, 2 more tries remain
(da1:umass-sim1:1:0:0): READ(10). CDB: 28 00 02 1f c0 00 00 00 80 00
(da1:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(da1:umass-sim1:1:0:0): Retrying command, 1 more tries remain
(da1:umass-sim1:1:0:0): READ(10). CDB: 28 00 02 1f c0 00 00 00 80 00
(da1:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(da1:umass-sim1:1:0:0): Retrying command, 0 more tries remain
(da1:umass-sim1:1:0:0): READ(10). CDB: 28 00 02 1f c0 00 00 00 80 00
(da1:umass-sim1:1:0:0): CAM status: CCB request completed with an error
(da1:umass-sim1:1:0:0): Error 5, Retries exhausted
g_vfs_done():da1s2a[WRITE(offset=5245009920, length=32768)]error = 6
g_vfs_done():da1s2a[WRITE(offset=5245075456, length=32768)]error = 6
g_vfs_done():da1s2a[WRITE(offset=13767868416, length=32768)]error = 6
g_vfs_done():da1s2a[WRITE(offset=13767933952, length=32768)]error = 6
g_vfs_done():da1s2a[READ(offset=18190761984, length=1048576)]error = 6
UFS: forcibly unmounting /dev/da1s2a from /mnt
となって、データベースHDDは、強制アンマウントされてしまうという具合。何度か試してみたものの、引っかかる場所は同じ。つまり、OSではなく、データベースファイルが置かれているセクターが壊れてしまったための OS 停止だったというわけ。
OSは諦めるとしても、データベースは吸い出さないといけない。WordPress からエクスポートしたバックアップはあるものの、約2か月分のXMLデータを取ってない。12/31にエクスポートしておこうかと思ったものの、眠かったためか結局エクスポートしなかった。やべ。
(仮に全コンテンツのエクスポートデータがあったとしても、それはコンテンツデータだけなので、統計情報は含まれていません。やっぱり、wordpress用データベースの復旧が必要になります。)
HDDをOff、Onして、fsck かけて、マウントして、ファイルを吸い出し、強制アンマウント というループを繰り返して、バックアップするためのコマンドを変えたり、手動コピーしたりと、数時間かけて、データ吸出しを一旦完了。読めなかったセクターのデータは欠けたまま。
これを、MySQLデータベース分離前、WebサーバーとMySQLサーバーを同時に動かしていた状態に戻せば仮復旧できるはず。
/var/db/mysql 以下に吸い出したファイルを配置、(不良セクターを、読み込もうとするとHDDがオフラインになってしまうため、一部欠けがある)mysql サーバーを起動してみると、、、、、、起動失敗。
mysql のログには次のように記録されていました。
2024-01-01T20:07:01.6NZ mysqld_safe Starting mysqld daemon with databases from /var/db/mysql
2024-01-01T20:07:05.379169Z 0 [System] [MY-010116] [Server] /usr/local/libexec/mysqld (mysqld 8.0.33) starting as process 91687
2024-01-01T20:07:06.123400Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-01-01T20:07:07.419503Z 1 [ERROR] [MY-012671] [InnoDB] Encryption algorithm support missing: N
2024-01-01T20:07:07.434303Z 1 [ERROR] [MY-013183] [InnoDB] Assertion failure: log0recv.cc:3622:err == DB_SUCCESS thread 0x834140300
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
2024-01-01T20:07:07Z UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x850eb0000
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
[0x23b2415] +0x58000081a0
[0x23b25f6] +0x58000081a0
[0x2f38f1a] +0x58000081a0
[0x32ce7d3] +0x58000081a0
[0x31dd2af] +0x58000081a0
[0x31db530] +0x58000081a0
[0x3287b97] +0x58000081a0
[0x2f8c9bc] +0x58000081a0
[0x2d64e39] +0x58000081a0
[0x2f10080] +0x58000081a0
[0x2000fd5] +0x58000081a0
[0x33498f2] +0x58000081a0
[0x824edaa7a] _pthread_create+0x8ca
[0x0] +0x8ca
stack_bottom = 87be7eeb8 thread_stack 0x100000
「Encryption algorithm support missing: N」って何だ?
#innodb_redo ディレクトリ内の一部が破損しているため?
#innodb_redo ディレクトリの役目を検索してみると、データベースではなく、ワークファイルの模様。フォルダー名に redo って書いてある訳だから、データベースに対して行った操作を記録しておくバッファのようなものに見えます。
他の、MySQL8をインストールした後、データベースを一切作らず、放置しているホストの mysql ディレクトリと中身を比べてみると、ファイルの通し番号は異なるもののデータベースを作成していなくても通し番号ファイルは存在するので勝手に作られるワークファイルのようです。消しても大丈夫でしょう。
アーカイブはあるので、#innodb_redo ディレクトリ以下を全部抹消。その後、mysql サービスを起動してみたところ、大量(1000行くらい)の「[ERROR] [MY-011972] [InnoDB] Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB redo log files. Please refer to http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html for information about forcing recovery.」が記録されるものの、mysql デーモンは起動。
やったね。
あんなに苦労しなくても、元々、壊れたファイル要らなかったんじゃん。
この後で、外部データベースに接続するよう設定してある wp-config.php ファイルをローカルホストの mysql に向けるように設定し直して、仮復旧終了。
文章で書けばこれくらいですが、壊れつつあるHDDからデータを吸い出すのって、頻繁にOSが停止するため、すごく時間が掛かる。Webサーバーのログから時間をチェックすると、22時頃 Webサーバーをダウンさせて、6時頃再起動できたので、作業時間は8時間くらいかかったことになります。
2024年は初日から(地震の他に)大トラブル発生でした。