叫ぶうさぎの悪ふざけ

うさぎが目印のWebエンジニアが、得たことや思ったことを言の葉に乗せて叫ぶ場所です。

トップ > 学習記録：12月14日(金)：【MySQL8.0アップグレード】5.7.19->5.7.24->8.0.11 アップグレード手順【5.7.24 アップグレード後編-エラーを調べる】

学習記録：12月14日(金)：【MySQL8.0アップグレード】5.7.19->5.7.24->8.0.11 アップグレード手順【5.7.24 アップグレード後編-エラーを調べる】

これは 俺のインプットアウトプット記録 Advent Calendar 2018 の14日目のエントリーです。

結論からいうと、どうも サイズの大きなibdファイルが失われている ようです。結果、データファイルが読み取れず、アップグレードのチェック時にエラーとなっていた模様。

今回はそのエラーを /var/log/mysqld.log から、なるべく1つずつ調べていきます。

昨日の振り返り

趣味なので振り返りからやっていきます。

/var/lib/mysql/mysql_upgrade_info ファイルが書き込めなかった

昨日はパーミッションの関係で、以下のファイルが書き込めなかったのを解決し、そのさきへ…というところで止まっていました。

Could not create the upgrade info file '/var/lib/mysql/mysql_upgrade_info' in the MySQL Servers datadir, errno: 13

12月15日(土) 1:36 追記

最強の外部API神であるお豆腐さん が今日と昨日のエントリーをみてくれて、なんとまとめてくださった…あなたが神か（神です）。本当にありがとうございます！

とある豆腐のエラー考察（未完）

で、 /var/lib/mysql/mysql_upgrade_info ファイルが書き込めなかった の正解を引用します。

さすがやで…根拠をインクルードファイルで提示までしてくださる…。というわけで、 mysql_upgrade 実行ユーザーが vagrantユーザーで、/var/lib/mysql への書き込み権限を持たなかったため でした。（あってるかな？）

これもっかい最初からやり直そうかなって思ってます。

/var/lib/mysql/ パーミッション変更し、mysql_upgradeを再実行

で、パーミッションを変更してmysql_upgradeを実行し、ファイルが出力されるところまで実行しました。

$ sudo chmod 775 /var/lib/mysql
$ ls -lda /var/lib/mysql
drwxrwxr-x 7 mysql mysql 4096 12月 13 22:53 /var/lib/mysql
$ mysql_upgrade -uroot -p
Enter password: 
(中略)
Upgrade process completed successfully.
Checking if update is needed.

バージョン情報のテキストファイルだった

で、結果としては 5.7.24 のアップグレードのバージョンが出力されるファイルだったようです。

$ cat /var/lib/mysql/mysql_upgrade_info
5.7.24

それから

とはいえ本題のエラーはまだこれからでした。

Tablespace is missing for table

で、続いて昨日は以下のエラーが出て、特定のテーブルが5.7.19から5.7.24へのアップグレードされる段階でエラーを出力していました。ちなみにMySQL自体はアップグレードができています。

$ mysql_upgrade -uroot -p
(中略)
mamy1326.c_log
Warning  : InnoDB: Tablespace is missing for table mamy1326/c_log.
Error    : Tablespace is missing for table `mamy1326`.`c_log`.
error    : Corrupt

そこで今日は、このエラーの原因を究明、解決し、テーブルを復旧するところまで進めたいです。

試しにSELECT

MySQLの起動はできたので試しにSELECTしてみましたが、同じエラーになります。 というわけでこれは趣味。丁寧に調べていきます。

mysql> select * from c_log limit 1;
ERROR 1812 (HY000): Tablespace is missing for table `mamy1326`.`c_log`.

/var/log/mysqld.log エラーログを見る

困った時のエラーメッセージ。素直にエラーログをみます。

該当部分を抜き出し

今回のテーブルの部分のみ抜き出してみました。 色々出てますので、1つずつ調べてみます。趣味ですので。

2018-12-14T13:21:28.160781Z 2 [ERROR] InnoDB: Failed to find tablespace for table `mamy1326`.`c_log` in the cache. Attempting to load the tablespace with space id 139
2018-12-14T13:21:28.160847Z 2 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2018-12-14T13:21:28.160856Z 2 [ERROR] InnoDB: The error means the system cannot find the path specified.
2018-12-14T13:21:28.160862Z 2 [ERROR] InnoDB: Cannot open datafile for read-only: './mamy1326/c_log.ibd' OS error: 71
2018-12-14T13:21:28.160868Z 2 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2018-12-14T13:21:28.160873Z 2 [ERROR] InnoDB: The error means the system cannot find the path specified.
2018-12-14T13:21:28.160880Z 2 [ERROR] InnoDB: Could not find a valid tablespace file for `mamy1326/c_log`. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
2018-12-14T13:21:28.160996Z 2 [Warning] InnoDB: Cannot calculate statistics for table `mamy1326`.`c_log` because the .ibd file is missing. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting.html for how to resolve the issue.

Failed to find tablespace for table mamy1326.c_log in the cache. Attempting to load the tablespace with space id 139

直訳すると以下になります。

キャッシュ内のテーブル mamy1326.c_logのテーブルスペースを見つけることができませんでした。スペースID 139で表スペースをロードしようとしています

何のことやらさっぱりです。 グーグル先生に頼っても「クラッシュしたんで復旧してや」って記事ばかり。俺はこのエラーメッセージの意味と原因を知りたいんじゃああああああ！

と思うけど他にもエラーメッセージがたくさん出てるので次々調べてみます。

Operating system error number 2 in a file operation.

これも直訳します。

ファイル操作中のオペレーティング・システム・エラー番号2。

ざっくりとしかわからへんがな(´･_･`)

次調べましょう。

The error means the system cannot find the path specified.

これも直（ry

エラーは、システムが指定されたパスを見つけることができないことを意味します。

お、これは前のエラーと繋がってることを意味しそうです。何かパス間違ってるんかな。ibdファイルかな。うーん。

しかし my.cnf へのパスの情報はこれくらいしか設定してない。

[mysqld]
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
symbolic-links=0
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

とりあえず次のエラーを調べます。

Cannot open datafile for read-only: './mamy1326/c_log.ibd' OS error: 71

おおおおっ。これは…ッ！ibdファイルが開けない…ッ！パーミッションか…ッ！

突然のJOJO風、失礼しました。取り乱しました。

やっとエラーメッセージみただけでわかりそうな感じになってきたので、ファイル確認します。

$ sudo ls -la /var/lib/mysql/mamy1326/c_log.ibd
ls: /var/lib/mysql/mamy1326/c_log.ibd にアクセスできません: そのようなファイルやディレクトリはありません

テーブルの実体ファイルがないじゃない。ちなみに定義ファイルはありました。

Could not find a valid tablespace file for mamy1326/c_log. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.

結局のところ、最後のエラーメッセージで、公式をみてトラブルシューティングをするべし、とありがたくも指摘までいただけているのでみていくことにします。

というかこれ、アップグレードしようとして、ファイルでかすぎて変換できなかったんじゃないかな、と今の時点で予測を立ててます。

公式を参照する

公式の 14.19.3 InnoDB データディクショナリの操作のトラブルシューティング を参照します。（内容は全て翻訳機にかけた内容です）

序文

テーブル定義に関する情報は、.frm ファイルと InnoDB データディクショナリの両方に格納されます。.frm ファイルをあちこちに移動したり、データディクショナリの操作の最中にサーバーがクラッシュしたりすると、これらの情報のソースに整合性がなくなることがあります。

frmファイルにテーブル定義、ibdファイルがデータディクショナリ、という認識です。これがクラッシュしたら整合性取れなくなるよと最初に言われています。

データファイルを開くことができません。

公式の前半部分に、今回のエラーメッセージズバリの内容が書かれていました。innodb_file_per_tableパラメータはデフォルトでONになっているので、表領域は共有ではなく個別領域です。その表領域である .ibd ファイルが欠落しているよと言われます。

innodb_file_per_table （デフォルト）有効にした場合、次のメッセージが起動時に表示されることがあります ファイルあたりのテーブル 表領域のファイル（.ibdファイル）が欠落しています。

はい、その通りでした。サンプルのエラーメッセージも今回のものとほぼ同じです。

[ERROR] InnoDB: Operating system error number 2 in a file operation.
[ERROR] InnoDB: The error means the system cannot find the path specified.
[ERROR] InnoDB: Cannot open datafile for read-only: './test/t1.ibd' OS error: 71
[Warning] InnoDB: Ignoring tablespace `test/t1` because it could not be opened.

で、解決方法としては、DROP TABLEしなさいと書かれています。

これらのメッセージに対処するには、DROP TABLEステートメントを発行して欠落しているテーブルに関するデータをデータ辞書から削除します。

DROP TABLEしてみる

.ibd ファイルが欠落した理由は今のところわかっていませんが、幸いこのテーブルはバックアップがあります。そこで素直に公式に従い、DROP TABLEしてみます。

ちなみにログインした結果から、 Server version: 5.7.24-log MySQL Community Server (GPL) が確認できます。

$ mysql -uroot -p mamy1326
Enter password: 
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 3
Server version: 5.7.24-log MySQL Community Server (GPL)

Copyright (c) 2000, 2017, Oracle and/or its affiliates. All rights reserved.

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> DROP TABLE c_log;
Query OK, 0 rows affected (0.02 sec)

無事DROP TABLEすることができました。

テーブル定義も消えてますね。

$ sudo ls -la /var/lib/mamy1326/c_log.*
ls: /var/lib/mamy1326/c_log.* にアクセスできません: そのようなファイルやディレクトリはありません

次の課題

DROP TABLEしたものの、こいつを復元するのはどうやって？がまだわかっていません。

バックアップからリストアするんだろうな。ということでリストアするとは思います。

今回はここまで

さて、いったん学習時間としては時間切れ。引き続き明日調べていきます。

それにしても5.7.19で構築した環境にテスト的に大きめなデータを入れた状態で、マイナーバージョンアップしただけでもこういうことが起きる。いい経験をしているなーと思います。

現段階での予測では、以下の状態だったのかもしれないなあと思ったりしてます。

  • vagrantは40GB
  • テーブルスペースの総容量は20GBちょっと
  • ストレージの空き容量は4GB程度
  • なんらかの理由でデータファイルを消した
    • 手で消してた？
  • またはmysql_upgrade実行時に復元できなかった
    • 容量不足？

12月15日(土) 2:10 追記

/var/log/mysqld.log を遡ってみると前から起きているエラーがあった。

  • そもそもibdファイルを作成できていなかった？
    • 過去のmysqld.logを遡ったら Cannot open datafile for read-only: './mamy1326/c_log.ibd' OS error: 71
    • そもそも去年の7月に環境作ったとき、ディスクフルで書き込めてなかった
      • 2017-07-07T22:01:02.800765Z 3 [ERROR] /usr/sbin/mysqld: The table 'c_log' is full
    • よってvagrantのbox容量を40Gに拡張したのち、リストアしていた
      • しかしそれでもibdファイルは正しく作られていなかったか、どこかで消えていた
      • 2017-09-21の時点でも同じように、ibdファイル読めないよ（ないよ）と言われていた
      • 2017-09-21T13:53:39.939744Z 0 [ERROR] InnoDB: Cannot open datafile for read-only: './mamy1326/c_log.ibd' OS error: 71
  • ログには別のエラーも出ていたが、MySQLの起動には成功していた
    • 例えばこれ
    • 2018-04-29T13:07:39.271664Z 3 [ERROR] InnoDB: Failed to find tablespace for tablemamy1326.c_login the cache. Attempting to load the tablespace with space id 139
    • このエラー出てる場合、MySQLの起動に失敗する事例しか検索できなかったけど、なんでだろう…
  • ibdファイルがないため、統計情報の計算ができません、と言われているので、この時点で欠落していた
    • 2018-04-29T13:08:18.405618Z 3 [Warning] InnoDB: Cannot calculate statistics for tablemamy1326.c_logbecause the .ibd file is missing. Please refer to http://dev.m ysql.com/doc/refman/5.7/en/innodb-troubleshooting.html for how to resolve the issue.

つまり、 アップグレード実行時に .ibdファイルが欠落していた ことがわかりました。

今後の進め方

幸いバックアップデータがあるので、リストアしてもう一度実行してみようと思います。

今度は、全てのibdファイルが揃っていることを確認した上で。

で、ストレージ容量不足なのか、データが悪いのか、順番に切り分けしてみようと思います。

いやーでも手動でibdファイルは消さないと思うんだよなあ…。

12月15日(土) 2:15 追記

最初から .ibd ファイルがなかったことが判明したので、ちょっと遠回りだけど以下の方法で再実行してみようと思います。

  • 5.7.19 の環境を作る
  • リストアする
  • .ibdファイルが揃っていることを確認する
    • 今回エラーのあったテーブルにSELECTできることも確認する
  • 5.7.24 へアップグレードする
  • 結果を確認する

んで、無事に 5.7.24 になったら、8.0.11 へさらにアップグレードしてみる計画です。

さて、明日もやるぞ！