雑な hinananoha

やさしいせかいをさがして三千里

MySQLの壊れたInnoDBファイル(.ibd)からのデータサルベージ / Restore corrupted (broken) InnoDB data from .ibd file

この記事の対象

この記事は、MySQL Serverが突然の死を迎えた上に、以下のような重症症状が出た方向けの記事です。

  • MySQLサーバが以下のようなエラーを吐いて起動に失敗する
2022-06-16T11:30:47.188361Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
11:30:48 UTC - mysqld got signal 11 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x0
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...
stack_bottom = 0 thread_stack 0x100000
エラーログの例
  • この際にsyslogに以下のようなsegfaultのエラーが出る
Jun 18 07:08:36 mysql-rescue systemd[1]: Starting MySQL Community Server...
Jun 18 07:08:37 mysql-rescue kernel: [167708.595846] ib_io_rd-1[104824]: segfault at fffffffffffffffb ip 000056024f5dc455 sp 00007efdf13c13e0 error 5 in mysqld[56024d1f4000+3a4e000]
Jun 18 07:08:37 mysql-rescue kernel: [167708.595868] Code: b6 47 fe 0f b6 4f ff 49 89 f8 49 21 f0 c1 e0 08 09 c8 0f b7 c8 41 f6 40 2a 80 74 c7 66 85 c0 75 bc 48 85 d2 0f 84 a3 01 00 00 <0f> b6 04 25 fb ff ff ff 0f 0b 90 41 0f b6 54 24 fd 41 80 64 24 fb
Jun 18 07:08:38 mysql-rescue systemd[1]: mysql.service: Main process exited, code=killed, status=11/SEGV
Jun 18 07:08:38 mysql-rescue systemd[1]: mysql.service: Failed with result 'signal'.
Jun 18 07:08:38 mysql-rescue systemd[1]: Failed to start MySQL Community Server.
  • innodb_force_recovery を1~3の値にしたが、何れも上記のエラーが出て起動できなかった
  • innodb_force_recovery を 4~6の値に設定した結果起動したが、MySQLのデータをサルベージするためにmysqldumpを実行した結果、途中で以下のような標準エラー出力が出て止まった
user@mysql-rescue:~$ sudo mysqldump -u root -q -x zabbix history > zabbix.history.sql
mysqldump: Error 2013: Lost connection to MySQL server during query when dumping table `history` at row: 32913217
  • 当該テーブル(上記エラーメッセージの "when dumping table" の後に書かれているテーブル名)に対して CHECK TABLE を実行すると上記と同じ問題が発生する

以下では、上記のような症状が出たMySQLサーバから、データを復旧する方法を記します。

急いでいる方:結論

以下のツールを使ってInnoDB内のデータを解析し、テーブルデータを取得します。
github.com

使い方が動画で、かつ英語でしか説明されていないため、以下、使用方法を記載します。

前提

以降記載する使い方の説明は以下の環境をベースにしています。

  • Ubuntu Server 20.04 LTS
  • MySQL Server 8.0 (8.0.29-0ubuntu0.20.04.3)

また、以下のパラメータを前提とします。

  • MySQLのデータディレクトリ(datadir): /var/lib/mysql (デフォルト値)
  • 復旧したいテーブルの格納されているschema名: schema_name
  • 復旧したいテーブルの名前: table_name
  • 該当のテーブルのカラム: `itemid`, `clock`, `value`, `ns`

上記の環境に該当しない場合、適宜読み替えて下さい。

上記を前提に、データの復旧の前に以下を確認して下さい。
① table_name.ibdがあることの確認
/var/lib/mysql/schema_name/table_name.ibd が存在することを確認して下さい。
上記ファイルは通常パーミッションが 600 が指定されているはずのため、sudoコマンド等を使って存在を確認して下さい。
② 復旧対象テーブルのテーブル定義(CREATE TABLE)の取得
復旧の際に必要ですので、CREATE TABLE文を用意して下さい。何らかのアプリケーションのtableの場合はその標準設定から取得しても良いですが、
そういったものが無い場合は、 innodb_force_recovery=6 にして起動した上で、テーブル定義を以下のコマンドで取得して下さい。

SHOW CREATE TABLE table_name

実施前に

① この作業を可能であれば本番環境で直接実施しないで下さい。
障害が発生した環境とは別に仮想マシン等を用意して、そこにMySQL Serverをインストール後、 /var/lib/mysql の中身を障害が発生した環境のものに入れ替えた上で実施することを強くお勧めします。
これは、InnoDBファイルの破損の原因が不良セクタなどのディスク起因だった場合に、汚染の拡大やより重症化する事を防ぐ目的もあります。
② ディスクの空き容量を確認して下さい。
この作業では、復旧したいテーブルの中身を二回に分けて吐き出すため、単純計算すると当該テーブル内のデータの2倍のデータを吐き出します。十分な余裕を持ったディスク容量のマシン(VM)で実施して下さい。

ツールの導入

~$ apt update && apt install build-essential bison flex -y
~$ git clone https://github.com/twindb/undrop-for-innodb.git
~$ cd undrop-for-innodb
~/undrop-for-innodb$ sudo make

上記のツールの依存である build関連のツールとbison, flexをインストールした後、リポジトリをcloneしてmakeします。導入は以上です。

テーブル定義の用意

「前提」で記述したとおり、予め取得したテーブル定義(CREATE TABLE文の形)をSQLファイルの形で記録しておきます。

~/undrop-for-innodb$ echo "CREATE TABLE ~~~~" > table_def.sql

pageデータの抽出

~/undrop-for-innodb$ sudo ./stream_parser -f /var/lib/mysql/schema_name/table_name.ibd

成功すると、カレントディレクトリに pages-table_name.ibd というディレクトリが生成されます。
なお、以下のエラーが出たときは、既に何らかの理由でそのディレクトリがある場合なので、一回そのディレクトリを削除してもう一回実行して下さい。

Could not create directory pages-history.ibd
mkdir(): File exists

ディレクトリの中身は以下の通りになってます。

~/undrop-for-innodb$ ls -la pages-table_name.ibd/
total 16
drwxr-xr-x  4 root     root     4096 Jun 17 10:12 .
drwxrwxr-x 10 user    user 4096 Jun 17 13:01 ..
drwxr-xr-x  2 root     root     4096 Jun 17 10:12 FIL_PAGE_INDEX
drwxr-xr-x  2 root     root     4096 Jun 17 10:12 FIL_PAGE_TYPE_BLOB

~/undrop-for-innodb$ ls -la pages-table_name.ibd/FIL_PAGE_INDEX
total 3348240
drwxr-xr-x 2 root root       4096 Jun 17 10:12 ./
drwxr-xr-x 4 root root       4096 Jun 17 10:12 ../
-rw-r--r-- 1 root root 2386853888 Jun 17 10:12 0000000000002517.page
-rw-r--r-- 1 root root 1041727488 Jun 17 10:12 0000000000002518.page

FIL_PAGE_INDEXの中身の .page ファイルの名前(数字) やファイル数は異なる可能性がありますが、このような形でファイルが生成されていれば、データの抽出に成功しています。
(もし、上記以外のディレクトリがある場合は、気にしないで下さい。)
多くの場合、FIL_PAGE_INDEX 内で一番数字が小さいファイル名のpageファイルがそのテーブルのデータを保有していますので、そのファイルを使ってデータの復元を行います。

データの救出

~/undrop-for-innodb$ sudo ./c_parser -f pages-table_name.ibd/FIL_PAGE_INDEX/000000000000251.page -t table_def.sql -b pages-table_name.ibd/FIL_PAGE_TYPE_BLOB > table_data 2> table_data.sql

000000000000251.page の所には、 FIL_PAGE_INDEX 内に入っている最も値の小さいファイル名を入れて下さい。
このコマンドは、復旧元のテーブルデータが大きければ大きいほど時間が掛かります。気長に待ちましょう。
なお、table_data.sql に復旧の進捗が表示されるので、別の窓を開いた上でそれを使って確認するのもありです。

~/undrop-for-innodb$ sudo tail -f table_data.sql
-- 2.46% done
-- 2.81% done
-- 3.16% done
-- 3.51% done
-- 3.87% done
-- 4.22% done
-- 4.57% done
-- 4.92% done

復旧が完了すると、table_data と table_data.sql の2つのファイルが生成されます。
table_data.sqlは、ファイルの末尾が以下のようになっていれば成功です。

-- 99.81% done
SET FOREIGN_KEY_CHECKS=0;
LOAD DATA LOCAL INFILE '(null)/dumps/default/table_name' REPLACE INTO TABLE `table_name` CHARACTER SET UTF8 FIELDS TERMINATED BY '\t' OPTIONALLY ENCLOSED BY '"' LINES STARTING BY 'table_name\t' (`itemid`, `clock`, `value`, `ns`);
-- STATUS {"records_expected": 38451309, "records_dumped": 37896758, "records_lost": true} STATUS END

SQL文の一部は異なっていて構いませんし、最終行のSTATUSの中身も異なっていて構いません。ファイル内に何らかのエラーと思しき表記があったり、そもそもLOAD DATA文が無い場合は、失敗している可能性があります。
table_dataは以下のような形でテーブルの生データがTAB区切りで記録されています。

-- Page id: 4, Format: COMPACT, Records list: Valid, Expected records: (107 107)
-- Page id: 4, Found records: 0, Lost records: YES, Leaf page: NO
-- Page id: 6, Format: COMPACT, Records list: Valid, Expected records: (113 113)
000002FA0E06    000000006BF9    81000000B6014C  history 34056   1612590149      115.000000      751508244
000002FA0E07    000000006BF9    81000000B6015B  history 34050   1612590149      41.000000       751508244
000002FA0E09    000000006BF9    81000000B60179  history 34021   1612590149      29.000000       751508244
000002FA0E0A    000000006BF9    81000000B60188  history 34061   1612590149      100.000000      751508244
000002FA0E0B    000000006BF9    81000000B60197  history 34065   1612590149      65.000000       751508244

これにてデータの救出は完了です。

データのリストア

前述までの操作で得られた table_data.sql と table_data を復旧対象のサーバに転送し、正常に稼働するMySQLサーバに対してデータのインポートを行います。
この作業をする前に予め、当該データを格納する空のテーブルを作成して下さい。
(前提で作成した table_def.sql を使うと良いと思います)

データの復旧の前に、現在のMySQLサーバでは LOAD DATA LOCAL 構文が禁止されているので、LOAD DATA LOCAL が使えるようにします。

~$ mysql -u root -p
mysql> SET GLOBAL local_infile=on; 
Query OK, 0 rows affected (0.00 sec)

mysql> exit
Bye
~$

次に、table_data.sql 内の LOAD DATA LOCAL INFILE の後のパスを、現在のtable_data が置かれているフルパスに変更します。
例えば、/home/user/ に置かれてる場合は以下の通りにします。

LOAD DATA LOCAL INFILE '/home/user/table_data' REPLACE INTO TABLE `table_name` CHARACTER SET UTF8 FIELDS TERMINATED BY '\t' OPTIONALLY ENCLOSED BY '"' LINES STARTING BY 'table_name\t' (`itemid`, `clock`, `value`, `ns`);

最後に、データをインポートします。

~$ mysql --local-infile=1 -u root -p schema_name < table_data.sql

以上で完了です。
終了後、セキュリティの確保の観点から、LOAD DATA LOCALの保護を戻すことを強く推奨します。

~$ mysql -u root -p
mysql> SET GLOBAL local_infile=off; 
Query OK, 0 rows affected (0.00 sec)

mysql> exit
Bye
~$


もし、データの復旧の仕方だけ知りたい方は、ここでブラウザを閉じていただいて大丈夫です。
本当に、お疲れ様でした。

以下は、そもそも今回どのようなトラブルが発生して、どういった経緯を経た後にこの解決法に至ったのか、そして各ステップの詳細について、自分に対しての備忘録と、興味がある人と、より詳細を参考にして上記対処の適切さを評価したい方などに向けて述べます。

今回の記事を書くに至った経緯

発生したこと

今回問題が発生したのは、我が家の環境を監視しているZabbixサーバ内のMySQL Serverでした。我が家では、Zabbixの監視データの一部と、電力消費量と部屋の温度等を記録したInfluxDBのデータをGrafanaを使ってダッシュボード化し、机の隅っこにいつも表示させています。
そのGrafanaで突然、Zabbixで監視しているデータのみが表示出来なくなりました。何が起きたか確認すべくZabbix Serverにログインしようとすると、DBと接続できない旨のエラーが表示されており、MySQLサーバが異常停止していました。
その時、当該サーバには以下のようなログが出ていました*1

2022-06-16T11:30:47.188361Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
11:30:48 UTC - mysqld got signal 11 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x0
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...
stack_bottom = 0 thread_stack 0x100000

初動対処

上記エラーメッセージに記載があるとおり、そしてメッセージで念のため調べた結果、上記のエラーが出るのは、MySQL Serverにバグが発生した場合か、InnoDBデータが破損した場合ということがわかりました。
また、InnoDBデータの破損だった場合は、不良セクタなどによるディスク・データ破損等の可能性もあるため、取り急ぎ当該MySQL Serverのデータ(/var/lib/mysql 内)をtarで固めてサルベージした*2後、ファイルシステムのチェックを行いました。
結果、ファイルシステムは無事で、MySQL ServerのInnoDBファイルの復旧のみが課題となりました。

エラー調査

まず最初に「mysqld got signal 11」で調べると以下の記事がヒット。
yoku0825.blogspot.com

“signal 6” はアサーション(主にInnoDB)、 “signal 11” はバグな傾向がある。

とのことで、MySQLのバグの可能性を考慮して、直近でunattended-upgrade等でMySQLのアップデートがされたか確認したが、なし。
また、当該サーバだけの事象の可能性を疑い、/var/lib/mysqlの中身を、検証用に建てた同じOSのVMに移動し、MySQL Serverを起動したが、同様のエラーで起動しないことが確認できました。そのため、

何度起動しようとしても “signal 11” で落ち 続ける ならデータが壊れている && そのエラーハンドルにバグがある予感。

とのことで、この時点でInnoDBの破損を疑いました*3

何より、バグ調査よりも、当該DBがZabbixのDBということもあり、一刻も早く監視を復旧する必要があるため、ここではInnoDBが破損した前提でデータの復旧に方針を切り替えました。

InnoDB故障時のデータ復旧方法調査

InnoDB broken」や「InnoDB rescue」などで調べ、多数の記事がヒットしましたが、おおよそ以下の記事のような内容がヒット。
qiita.com

要は、

1. MySQLサービスを停止する(同時に、MySQLに関連するサービスも停止。ここでは、zabbix-server.serviceを停止しました)
2. /var/lib/mysql の中身をバックアップする
3. /etc/mysql/my.cnf(Ubuntuの場合は、/etc/mysql/mysql.conf.d/mysqld.cnf) の [mysqld] セクションに innodb_force_recovery = 1(~3) をセットして起動する
4. 起動したらmysqldumpを使ってデータをサルベージ

という流れ。
なお、 innodb_force_recovery については、MySQLの以下のページを参照。
dev.mysql.com

全データサルベージ(失敗)

ということで、innodb_force_recoveryを1~3に順番に上げながら試すも、同じエラーで起動失敗。
出来る事もないので、(データのバックアップを取っているというのもあり)4以上の値も試した結果、最終的に最大値である innodb_force_recovery=6 で以下のようなログと共に起動。

2022-06-18T07:12:04.696851Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.29-0ubuntu0.20.04.3) starting as process 107054
2022-06-18T07:12:04.717062Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2022-06-18T07:12:05.290480Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended.
2022-06-18T07:12:05.804337Z 1 [Warning] [MY-011018] [InnoDB] Skip updating information_schema metadata in InnoDB read-only mode.
2022-06-18T07:12:05.805431Z 1 [Warning] [MY-010005] [Server] Skip re-populating collations and character sets tables in InnoDB read-only mode.
2022-06-18T07:12:05.897376Z 2 [Warning] [MY-011018] [Server] Skip updating information_schema metadata in InnoDB read-only mode.
2022-06-18T07:12:05.900989Z 0 [Warning] [MY-010970] [Server] Skipped updating resource group metadata in InnoDB read only mode.
2022-06-18T07:12:05.901083Z 0 [Warning] [MY-010970] [Server] Skipped updating resource group metadata in InnoDB read only mode.
2022-06-18T07:12:06.081735Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2022-06-18T07:12:06.112719Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2022-06-18T07:12:06.306109Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2022-06-18T07:12:06.306223Z 0 [System] [MY-013602] [Server] Channel mysql_main configured to support TLS. Encrypted connections are now supported for this channel.
2022-06-18T07:12:06.455443Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Bind-address: '127.0.0.1' port: 33060, socket: /var/run/mysqld/mysqlx.sock
2022-06-18T07:12:06.455686Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.29-0ubuntu0.20.04.3'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  (Ubuntu).

とりあえずRead-onlyモードで起動しました。

というわけで、記事に記載の通り、mysqldumpを実行したところ、以下のエラーで停止しました。

user@mysql-rescue:~$ sudo mysqldump -u root -q -x --all-databases > mysqldump.dump
mysqldump: Error 2013: Lost connection to MySQL server during query when dumping table `history` at row: 32913217

このとき、裏でerror.logに出ていたエラーは以下の通り。

2022-06-18T07:22:44.141575Z 9 [ERROR] [MY-013183] [InnoDB] Assertion failure: btr0pcur.cc:334:btr_page_get_prev(next_page, mtr) == get_block()->page.id.page_no() thread 139985153079040
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.
07:22:44 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x7f50b80b20f0
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...
stack_bottom = 7f50d552ad50 thread_stack 0x100000
/usr/sbin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x41) [0x56178b3c1ad1]
/usr/sbin/mysqld(print_fatal_signal(int)+0x2fb) [0x56178a2627db]
/usr/sbin/mysqld(my_server_abort()+0x76) [0x56178a262926]
/usr/sbin/mysqld(my_abort()+0xe) [0x56178b3bbace]
/usr/sbin/mysqld(ut_dbg_assertion_failed(char const*, char const*, unsigned long)+0x349) [0x56178b6377b9]
/usr/sbin/mysqld(btr_pcur_t::move_to_next_page(mtr_t*)+0x1e0) [0x56178b68da50]
/usr/sbin/mysqld(row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)+0x12ed) [0x56178b597e1d]
/usr/sbin/mysqld(ha_innobase::general_fetch(unsigned char*, unsigned int, unsigned int)+0x1f8) [0x56178b4207d8]
/usr/sbin/mysqld(handler::ha_rnd_next(unsigned char*)+0x68) [0x56178a373438]
/usr/sbin/mysqld(TableScanIterator::Read()+0x24) [0x56178a4c6d14]
/usr/sbin/mysqld(Query_expression::ExecuteIteratorQuery(THD*)+0x376) [0x56178a1e26b6]
/usr/sbin/mysqld(Query_expression::execute(THD*)+0x33) [0x56178a1e2963]
/usr/sbin/mysqld(Sql_cmd_dml::execute(THD*)+0x186) [0x56178a1703d6]
/usr/sbin/mysqld(mysql_execute_command(THD*, bool)+0xa00) [0x56178a10c960]
/usr/sbin/mysqld(dispatch_sql_command(THD*, Parser_state*)+0x434) [0x56178a111574]
/usr/sbin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x1d68) [0x56178a113808]
/usr/sbin/mysqld(do_command(THD*)+0x116) [0x56178a1149d6]
/usr/sbin/mysqld(+0x1122698) [0x56178a253698]
/usr/sbin/mysqld(+0x27e1bcd) [0x56178b912bcd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8609) [0x7f50ff02e609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43) [0x7f50fe27e133]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f50b8263b50): is an invalid pointer
Connection ID (thread ID): 9
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

このエラーが出た当初は、具体的にどういった現象が発生して落ちたのか、までは理解できなかったものの、とりあえずMySQL Serverのzabbix schema内のhistoryテーブルが破損した、ということは分かりました。

zabbix.history以外のデータサルベージ(成功)

とりあえずhistoryテーブル以外を復旧すべく、以下の手順を取りました

  • zabbix schemaのhistory テーブルが問題を起こしているので、そのibdファイルを取り除く。
~# mkdir /var/lib/mysql.temp
~# mv /var/lib/mysql/zabbix/history.ibd /var/lib/mysql.temp/.
  • 一旦 innodb_force_recovery をコメントアウトして起動するも、失敗。順番に1から設定した結果、 innodb_force_recovery = 2で無事起動。
  • この状態で、MySQLのシェルに入って history テーブルをDROPする。
~# mysql -u root -p
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 8
Server version: 8.0.29-0ubuntu0.20.04.3 (Ubuntu)

Copyright (c) 2000, 2022, Oracle and/or its affiliates.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> use zabbix;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql> drop table history;
Query OK, 0 rows affected (0.09 sec)

mysql> exit
Bye
~#
  • この過程で、error.logには以下のメッセージが流れる。
2022-06-18T08:53:09.182513Z 8 [ERROR] [MY-012592] [InnoDB] Operating system error number 2 in a file operation.
2022-06-18T08:53:09.182760Z 8 [ERROR] [MY-012593] [InnoDB] The error means the system cannot find the path specified.
2022-06-18T08:53:09.182826Z 8 [ERROR] [MY-012216] [InnoDB] Cannot open datafile for read-only: './zabbix/history.ibd' OS error: 71
2022-06-18T08:53:09.183435Z 8 [Warning] [MY-012049] [InnoDB] Cannot calculate statistics for table `zabbix`.`history` because the .ibd file is missing. Please refer to http://dev.mysql.com/doc/refman/8.0/en/innodb-troubleshooting.html for how to resolve the issue.
  • 当然だが、この流れでzabbix.historyは削除されたので、この状態で再度mysqldumpを実施。
~# mysqldump -u root -p -q -x --all-databases > all_dump_wo_zabbix_history.dump
  • 無事、zabbix.history以外のdumpに成功した。
  • 終了後、再度MySQLサーバを停止し、 /var/lib/mysql の中身を、このステップを実施する前(=バックアップした /var/lib/mysql の中身)に戻す(zabbix.historyの復旧を試みるため)
zabbix.historyの復旧方法調査

zabbix.history以外のデータは復旧出来たので、ここからはzabbix.historyの中身を復旧する方法を調査しました。
しかし、復旧方法はだいたいこの章の頭に書いた方法しかなく、唯一見つかった方法は、以下の記事に書かれているような方法でした。
https://support.plesk.com/hc/ja/articles/213939865--%E6%89%8B%E9%A0%86-MySQL-%E3%83%87%E3%83%BC%E3%82%BF%E3%83%99%E3%83%BC%E3%82%B9%E3%81%A7%E3%81%AE-InnoDB-%E7%A0%B4%E6%90%8D%E3%82%92%E4%BF%AE%E5%BE%A9%E3%81%99%E3%82%8B%E3%81%AB%E3%81%AF

1. テーブルのコピーを試みます。

CREATE TABLE new_table LIKE crashed_table;
INSERT INTO new_table SELECT * FROM crashed_table;

2. コピーが正常に作成されたら、破損したテーブルを削除して、新しいテーブルを古いテーブルの名前に変更します。

DROP TABLE crashed_table;
RENAME TABLE new_table TO crashed_table;

しかし、この方法はあくまで innodb_force_recovery < 4 で起動できた場合のみで、4以上の場合はそもそもInnoDBが読み取り専用になるため、1. の時点で詰みます。

他にもこちらの記事も参照しました。
https://support.cpanel.net/hc/en-us/articles/1500006010582-InnoDB-Corruption-Repair-Guide
この記事は、おそらく今回のような場合でない、「一般的な」事例の場合は非常に有用な記事でしたが、残念ながらコーナーケースでした。

最終的にたどり着いた記事がこちら。
dba.stackexchange.com
この記事の質問者は、「innodb_force_recovery を付けて起動した上で mysqldumpやmysqlcheckを実行すると、「Lost connection to MySQL server」となる」と、私と全く同じ症状を訴えていました。
この記事のベストアンサーは以下の通りになっていますが、

mysqlcheck won't fix corruption in InnoDB table. You need to dump data from the table and re-create it.

Start MySQL with innodb_force_recovery option. Try values from 1 to 6 until MySQL starts.

Dump the table with mysqldump.

Drop the table.

Restart MySQL w/o innodb_force_recovery.

Reload the dump.

重要なのは、このベストアンサーに付けられた、以下のコメント群でした。

MySQL starts normally even with the default value innodb_force_recovery=0. One should not play with this setting as values of innodb_force_recovery equal to 4 or greater are considered dangerous (see dev.mysql.com/doc/refman/5.0/en/forcing-innodb-recovery.html). Does setting this value higher than 0 guarantee that mysqldump will run without crashing the MySQL server? –
dr_
Oct 2, 2015 at 7:14
It's on (innodb_file_per_table=1). –
dr_
Oct 5, 2015 at 7:04
1
Then take quux.ibd, upload it on recovery.twindb.com . If it manages to recover and shows valid records, extract the records from the ibd file with tool github.com/twindb/undrop-for-innodb . Then DROP the table and reload it from the dump to tool generates. –
akuzminsky
Oct 5, 2015 at 7:09
The table contains sensitive data, I'm not allowed to send it to an unknown online service. Besides, the files is more than 1Gb in size. –
dr_
Oct 5, 2015 at 7:20
I'm sure twindb does an excellent service, and to be honest I'd be happy to upload the data to see if they can repair it. However giving the database to external people is not an option unless they sign a NDA. It's not me who makes the rules. The table got corrupted after a malfunction of the storage system, by the way. What do you mean by step #2? –
dr_
Oct 5, 2015 at 7:35
2
It's perfectly fine that you can't upload the ibd file. By step #2 I mean "extract the records from the ibd file with tool github.com/twindb/undrop-for-innodb". Particularly, you need to follow scenario described in twindb.com/recover-corrupt-mysql-database –
akuzminsky
Oct 5, 2015 at 7:40
Thanks for the tip. I've tried undrop-for-innodb but it seems unable to recover the table, as dumps/default/quux contains only: -- Page id: 3, Format: COMPACT, Records list: Valid, Expected records: (0 0) -- Page id: 3, Found records: 0, Lost records: NO, Leaf page: YES Any other suggestion to recover the data? –
dr_
Oct 21, 2015 at 12:46
Just one empty page? It doesn't look correct. Are you sure you specify right index_id? –
akuzminsky
Oct 21, 2015 at 12:52
Yes, the index_id is correct. –
dr_
Oct 21, 2015 at 13:00
For at least 15 days the database is corrupt and degraded! Why don't you just hire experts to fix it ? If you don't like twindb call Percona. This problem is a no brainier –
akuzminsky
Oct 21, 2015 at 13:03
2
The answer "Hire someone to do it" to a question "How do I do X?" on SE is hardly useful. By the way, this is a development environment. –
dr_
Oct 21, 2015 at 15:02

残念ながらこの応答では、「このDBの中身はセンシティブな情報が入っている上にそのよくわからんツールは入れられない」ということで何の解決にも至ってなかったのですが、目を引いたのが

If it manages to recover and shows valid records, extract the records from the ibd file with tool github.com/twindb/undrop-for-innodb . Then DROP the table and reload it from the dump to tool generates.

でした。ここに記載のあったのが、冒頭にあった以下のツールです。
github.com

残念ながらこのツールの案内等が記載されてあったであろう twindb.com はアクセス出来なくなっていたのですが、READMEに添付されたYouTubeの動画のお陰で、インストール方法と使い方がわかり、無事データのサルベージに成功しました。


ここから先は、TwinDB data recovery toolkit を使った、詳細な使い方の説明を、公式の動画を元に説明します。

TwinDB data recovery toolkit を用いた破損したInnoDBファイルからのデータサルベージ方法

ここから先の記述は、以下の動画を元に作成しております。
www.youtube.com

なお、動画を見てこの内容を知りたい方は、7:52 あたりから見る事をオススメします。(それより前は主に環境構築とmakeするまでのお話です)

インストール方法

READMEに記載の通りで、非常にシンプルです。

1. 依存パッケージの make, gcc, flex, bison をインストールする

~# apt update
~# apt install make gcc flex bison -y

2. リポジトリをcloneしてmakeする。

~# git clone https://github.com/twindb/undrop-for-innodb.git
~# cd undrop-for-innodb
~/undrop-for-innodb# make

makeする際にwarningがいっぱい出るかと思いますが、これは上記の動画でも同じような状態なので、コンパイルがエラー終了しなければ問題ありません。

使い方

大まかな使い方は以下の通りです。

1. stream_parser に 該当のテーブルのibdファイルを入れ、pageファイルを得る
2. c_parser を使って page ファイルから内部データを復元する

以下、詳細です。
なお、以下の内容を記載するに当たり、InnoDBにおけるデータが保存されているInnoDB テーブルスペースの構造について、以下の記事を参考にしました。
これは記事を書くために読んだので、以下の内容について、多少の齟齬があるかもしれないことをお許し下さい*4。少なくともツールの利用には影響ありません。
qiita.com

1. stream_parser

stream_parser は、入力されたファイルからInnoDBのページを見つけるツールです。
/var/lib/mysql 内に入っている .ibd ファイルは InnoDB テーブルスペースと呼ばれるもので、現在のMySQLのメジャーバージョンにおいては、テーブル当たり1つ作成されます。
今回破損したzabbix schema内の history テーブルの場合、 /var/lib/mysql/zabbix/history.ibd がそれに該当します。
テーブルスペースにはテーブルやインデックスが格納されています。これらを、領域管理上はセグメント、と言います。
MySQLにおいてINDEXというと、PKやUK、INDEXとして指定した物を想定しますが、InnoDBにおいてはテーブルデータそのものもINDEXとして扱われます。これは通常、そのテーブルの一番最初のINDEX IDに格納されます。
ページ、はInnoDBにおける最小データ単位です。

https://camo.qiitausercontent.com/a396f7f5ec39a74a126a6878c907e8aa2e272f49/68747470733a2f2f71696974612d696d6167652d73746f72652e73332e616d617a6f6e6177732e636f6d2f302f3231363139362f37613266383439312d626261392d663132642d346539342d3635393531313262643765612e706e67
(前記記事より画像を引用)

さて、このツールでは、入力されたファイルにInnoDBのページがあるかを見て、見つけた場合は、ページタイプとINDEX ID毎に並べ替え、ファイルとして出力します。
つまり、上の画像で言う、緑色のページと青色のページのデータを、それぞれ適切な順番に並べ替えた上で、「INDEX60のセグメント」と「INDEX61のセグメント」としてそれぞれ出力します。
そして、このうち「INDEX 60のセグメント」が、多くの場合はテーブルの全てのデータが格納されているセグメントになる、というわけです。

というわけで、本件のテーブルスペースに対してコマンドを実行します。

~/undrop-for-innodb# ./stream_parser -f /var/lib/mysql/zabbix/history.ibd
Opening file: /var/lib/mysql/zabbix/history.ibd
File information:

ID of device containing file:        64768
inode number:                      1966269
protection:                         100640 (regular file)
number of hard links:                    1
user ID of owner:                      113
group ID of owner:                     117
device ID (if special file):             0
blocksize for filesystem I/O:         4096
number of blocks allocated:        6807560
time of last access:            1655536096 Sat Jun 18 07:08:16 2022
time of last modification:      1655359249 Thu Jun 16 06:00:49 2022
time of last status change:     1655545969 Sat Jun 18 09:52:49 2022
total size, in bytes:           3485466624 (3.246 GiB)

Size to process:                3485466624 (3.246 GiB)
Worker(0): 3.13% done. 2022-06-18 09:54:00 ETA(in 00:00:33). Processing speed: 96.000 MiB/sec
Worker(0): 6.02% done. 2022-06-18 09:54:00 ETA(in 00:00:32). Processing speed: 96.000 MiB/sec
Worker(0): 7.94% done. 2022-06-18 09:54:16 ETA(in 00:00:47). Processing speed: 64.000 MiB/sec
Worker(0): 9.15% done. 2022-06-18 09:54:45 ETA(in 00:01:15). Processing speed: 40.000 MiB/sec
Worker(0): 10.59% done. 2022-06-18 09:54:32 ETA(in 00:01:01). Processing speed: 48.000 MiB/sec
Worker(0): 13.72% done. 2022-06-18 09:53:59 ETA(in 00:00:27). Processing speed: 104.000 MiB/sec
Worker(0): 16.85% done. 2022-06-18 09:53:59 ETA(in 00:00:26). Processing speed: 104.000 MiB/sec
Worker(0): 19.74% done. 2022-06-18 09:54:01 ETA(in 00:00:27). Processing speed: 96.000 MiB/sec
Worker(0): 22.62% done. 2022-06-18 09:54:01 ETA(in 00:00:26). Processing speed: 96.000 MiB/sec
Worker(0): 24.07% done. 2022-06-18 09:54:28 ETA(in 00:00:52). Processing speed: 48.000 MiB/sec
Worker(0): 25.27% done. 2022-06-18 09:54:39 ETA(in 00:01:02). Processing speed: 40.000 MiB/sec
Worker(0): 26.47% done. 2022-06-18 09:54:39 ETA(in 00:01:01). Processing speed: 40.000 MiB/sec
Worker(0): 27.68% done. 2022-06-18 09:54:39 ETA(in 00:01:00). Processing speed: 40.000 MiB/sec
Worker(0): 29.60% done. 2022-06-18 09:54:16 ETA(in 00:00:36). Processing speed: 64.000 MiB/sec
Worker(0): 32.49% done. 2022-06-18 09:54:04 ETA(in 00:00:23). Processing speed: 96.000 MiB/sec
Worker(0): 35.62% done. 2022-06-18 09:54:02 ETA(in 00:00:20). Processing speed: 104.000 MiB/sec
Worker(0): 38.51% done. 2022-06-18 09:54:04 ETA(in 00:00:21). Processing speed: 96.000 MiB/sec
Worker(0): 41.16% done. 2022-06-18 09:54:06 ETA(in 00:00:22). Processing speed: 88.000 MiB/sec
Worker(0): 42.36% done. 2022-06-18 09:54:32 ETA(in 00:00:47). Processing speed: 40.000 MiB/sec
Worker(0): 44.77% done. 2022-06-18 09:54:08 ETA(in 00:00:22). Processing speed: 80.000 MiB/sec
Worker(0): 47.89% done. 2022-06-18 09:54:03 ETA(in 00:00:16). Processing speed: 104.000 MiB/sec
Worker(0): 51.02% done. 2022-06-18 09:54:03 ETA(in 00:00:15). Processing speed: 104.000 MiB/sec
Worker(0): 53.91% done. 2022-06-18 09:54:04 ETA(in 00:00:15). Processing speed: 96.000 MiB/sec
Worker(0): 56.80% done. 2022-06-18 09:54:04 ETA(in 00:00:14). Processing speed: 96.000 MiB/sec
Worker(0): 58.72% done. 2022-06-18 09:54:12 ETA(in 00:00:21). Processing speed: 64.000 MiB/sec
Worker(0): 60.89% done. 2022-06-18 09:54:10 ETA(in 00:00:18). Processing speed: 72.000 MiB/sec
Worker(0): 63.54% done. 2022-06-18 09:54:06 ETA(in 00:00:13). Processing speed: 88.000 MiB/sec
Worker(0): 65.94% done. 2022-06-18 09:54:08 ETA(in 00:00:14). Processing speed: 80.000 MiB/sec
Worker(0): 67.87% done. 2022-06-18 09:54:11 ETA(in 00:00:16). Processing speed: 64.000 MiB/sec
Worker(0): 69.07% done. 2022-06-18 09:54:21 ETA(in 00:00:25). Processing speed: 40.000 MiB/sec
Worker(0): 70.28% done. 2022-06-18 09:54:21 ETA(in 00:00:24). Processing speed: 40.000 MiB/sec
Worker(0): 71.48% done. 2022-06-18 09:54:21 ETA(in 00:00:23). Processing speed: 40.000 MiB/sec
Worker(0): 72.68% done. 2022-06-18 09:54:21 ETA(in 00:00:22). Processing speed: 40.000 MiB/sec
Worker(0): 75.33% done. 2022-06-18 09:54:09 ETA(in 00:00:09). Processing speed: 88.000 MiB/sec
Worker(0): 78.70% done. 2022-06-18 09:54:07 ETA(in 00:00:06). Processing speed: 112.000 MiB/sec
Worker(0): 81.59% done. 2022-06-18 09:54:08 ETA(in 00:00:06). Processing speed: 96.000 MiB/sec
Worker(0): 84.48% done. 2022-06-18 09:54:08 ETA(in 00:00:05). Processing speed: 96.000 MiB/sec
Worker(0): 86.16% done. 2022-06-18 09:54:12 ETA(in 00:00:08). Processing speed: 56.000 MiB/sec
Worker(0): 87.36% done. 2022-06-18 09:54:15 ETA(in 00:00:10). Processing speed: 40.000 MiB/sec
Worker(0): 88.57% done. 2022-06-18 09:54:15 ETA(in 00:00:09). Processing speed: 40.000 MiB/sec
Worker(0): 89.77% done. 2022-06-18 09:54:15 ETA(in 00:00:08). Processing speed: 40.000 MiB/sec
Worker(0): 90.97% done. 2022-06-18 09:54:15 ETA(in 00:00:07). Processing speed: 40.000 MiB/sec
Worker(0): 92.42% done. 2022-06-18 09:54:14 ETA(in 00:00:05). Processing speed: 47.984 MiB/sec
Worker(0): 94.10% done. 2022-06-18 09:54:13 ETA(in 00:00:03). Processing speed: 56.000 MiB/sec
Worker(0): 97.23% done. 2022-06-18 09:54:11 ETA(in 00:00:00). Processing speed: 104.000 MiB/sec
All workers finished in 46 sec

この作業の結果、pages-history.ibd というディレクトリが生成され、その中にデータが格納されます。

~/undrop-for-innodb$ ls -la pages-history.ibd/
total 16
drwxr-xr-x  4 root     root     4096 Jun 18 09:53 .
drwxrwxr-x 10 user     user 4096 Jun 18 09:53 ..
drwxr-xr-x  2 root     root     4096 Jun 18 09:53 FIL_PAGE_INDEX
drwxr-xr-x  2 root     root     4096 Jun 18 09:53 FIL_PAGE_TYPE_BLOB

FIL_PAGE_INDEXは、前述のインデックスが格納されたセグメントです。中身は以下の通りです。

~/undrop-for-innodb$ ls -la pages-history.ibd/FIL_PAGE_INDEX/
total 3348240
drwxr-xr-x 2 root root       4096 Jun 18 09:53 .
drwxr-xr-x 4 root root       4096 Jun 18 09:53 ..
-rw-r--r-- 1 root root 2386853888 Jun 18 09:54 0000000000002517.page
-rw-r--r-- 1 root root 1041727488 Jun 18 09:54 0000000000002518.page

ここで、zabbixのhistoryテーブルは、以下のCREATE構文から構成されています。

CREATE TABLE `history` (
  `itemid` bigint unsigned NOT NULL,
  `clock` int NOT NULL DEFAULT '0',
  `value` double NOT NULL DEFAULT '0',
  `ns` int NOT NULL DEFAULT '0',
  KEY `history_1` (`itemid`,`clock`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb3 COLLATE=utf8_bin

先程のと照らし合わせると、 INDEX ID 2517 のものがテーブルデータ、INDEX ID 2518のものが itemidとclockからなるセカンダリインデックスのものと推察されます。
つまり、テーブルデータの復元のためには、0000000000002517.page からデータが復元できれば良い、ということになります。

また、もう一つの FIL_PAGE_TYPE_BLOB は、テーブルデータのうち、BLOBデータがある場合に生成されるものです。こちらは、FIL_PAGE_INDEX から呼び出されるデータのため、こちらのデータも復元に用います。
ページタイプはこれ以外にも複数あるそうですが、今回の復元において重要なのはINDEXとBLOBだけなので、これ以上の説明は割愛します。

これで、テーブルスペースファイルから、セグメントを復元できましたので、セグメントからテーブル内のデータを復元します。

2. c_parser

c_parserは、InnoDBページをセグメント内のデータとして適切な順番に連続したファイル、すなわちstream_parserで出力された.pageファイルを入力として、この中身からデータを読み取るツールです。
このツールでテーブルの全てのデータを復元するには、以下のものが必要です。

1. そのテーブルのプライマリINDEX(最もINDEX IDの小さいセグメント)を格納した.pageファイル
2. (BLOBデータがある場合は) BLOBデータの格納されたフォルダ
3. CREATE TABLE構文で記載されたテーブル定義が格納されたsqlファイル

上記が揃っていてかつ適切だった場合、データの中身をタブ区切りのデータとして標準出力にデータを出力します。
また、標準エラー出力には、上記データを元にした、LOAD DATA IN FILE 構文を用いたSQLコマンド(と、このコマンドの進捗)を出力します。

ここでは、

として、以下のコマンドを実行することでデータが得られます。

~/undrop-for-innodb# ./c_parser -f pages-history.ibd/FIL_PAGE_INDEX/0000000000002517.page -t zabbix.history_def.sql -b pages-history.ibd/FIL_PAGE_TYPE_BLOB > zabbix.history 2> zabbix.history.sql

つまり、

  • -f:プライマリインデックスを格納した.pageファイルのパス
  • -t:テーブル定義の書かれたSQLファイルのパス
  • -b:BLOBのセグメントがある場合、それが格納されているディレクト

となります。

標準出力は、以下のようなデータが出力されます。

-- Page id: 4, Format: COMPACT, Records list: Valid, Expected records: (107 107)
-- Page id: 4, Found records: 0, Lost records: YES, Leaf page: NO
-- Page id: 6, Format: COMPACT, Records list: Valid, Expected records: (113 113)
000002FA0E06    000000006BF9    81000000B6014C  history 34056   1612590149      115.000000      751508244
000002FA0E07    000000006BF9    81000000B6015B  history 34050   1612590149      41.000000       751508244
000002FA0E09    000000006BF9    81000000B60179  history 34021   1612590149      29.000000       751508244
000002FA0E0A    000000006BF9    81000000B60188  history 34061   1612590149      100.000000      751508244
000002FA0E0B    000000006BF9    81000000B60197  history 34065   1612590149      65.000000       751508244
000002FA0E0C    000000006BF9    81000000B601A6  history 34058   1612590149      115.000000      751508244

標準エラー出力には、以下のようなデータが出力されます。

-- 0.35% done
-- 0.70% done
-- 1.05% done

-- 中略

-- 99.81% done
SET FOREIGN_KEY_CHECKS=0;
LOAD DATA LOCAL INFILE '(null)/dumps/default/history' REPLACE INTO TABLE `history` CHARACTER SET UTF8 FIELDS TERMINATED BY '\t' OPTIONALLY ENCLOSED BY '"' LINES STARTING BY 'history\t' (`itemid`, `clock`, `value`, `ns`);
-- STATUS {"records_expected": 38451309, "records_dumped": 37896758, "records_lost": true} STATUS END

標準出力に出力されているデータのうち、最初の3列はMySQLの内部用の非表示データで、4列目がテーブルネーム、5列目以降が実際のデータです。
このコマンドは、内部のデータの容量に応じて実行時間が変わります。私の場合、3900万レコード近くあり、コマンドの終了まで1時間ほどかかりました。
なお、標準エラー出力の最後に

{"records_expected": 38451309, "records_dumped": 37896758, "records_lost": true}

と記載されている通り、どうやらこのテーブルスペースファイルは破損の結果50万レコードほどを失ったようです。悲しい……。
どこのデータがどういう形で欠損したのか、調べたいところですが、データサイズが大きすぎてちょっと調査する気は失せました。まあ、3900万レコードの中なら50万レコードは1.2%程度ですし、自宅で運用している環境なので、その程度の欠落ならまあいいかな……と諦めました。

さて、これにてデータの復元は完了です。最後に、このデータを戻すことになりますが、その方法は最初の章に記載した通りですので、以下省略します。

最後に

本当に疲れました。というかこの情報にたどり着くまでが本当に大変でした。
この記事は、私みたいな状態になった人が、最後の助けとなることを祈って、書きました。

まあ、ただ、間違いなく、

こんなことするはめになる前に、定期的なバックアップや冗長構成化をしましょう。
が結論だと思います。私はしてませんでした……

これから、VM上にMySQLサーバのバックアップ環境を作ります。

ここまで読んで下さりありがとうございました。
なお、この記事は、復旧方法に関する説明と、私の備忘録的な経緯説明、及びツールの使い方に関する説明になります。間違いや、より適切な方法がありそうでしたら、是非ご指摘頂けますと幸いです。

*1:大元のサーバにあったログはMySQLの再インストールの過程で消えたので、検証や復旧を行う環境で再現したログを表示します

*2:この判断は我ながら超ベスト判断でした。これのお陰で検証環境で思う存分色々試すことができました

*3:バグもあったのかもしれませんが、バグを直したからといって起動してくれるような雰囲気ではなかったため……

*4:もし見つけた場合は優しくコメントして頂けるとありがたいです。