InnoDBログファイル（redoログ例 ib_logfile0、ib_logfile1）とデータファイルが同期していない状況になり、InnoDBログファイルのLSNが未来の番号を指してしまっている場合、以下のようなログがでてエラーになる。
2020-06-26T01:51:56.999337+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=7] log sequence number 7544572483711 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:56.999374+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.000535+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=2] log sequence number 7544572485197 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.000549+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.026524+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=5] log sequence number 7544572484325 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.026540+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.026697+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=6] log sequence number 7544572485308 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.026707+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.026849+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=57] log sequence number 7544572485308 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.026857+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.273586+09:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...
この場合、現在のLSNを最新のLSNより未来に変更する事で、復旧した。
現在のLSNから未来のLSNまでのトランザクションは破棄することになるので、注意。
力技もいいところなので、お勧めはしないけど、やらざるを得なくなった場合は
参考資料のリンク先も読んだうえで対応することをお勧めします。
※未知なトラブルがあるかも知れないので、やるとしても自己責任で行ってください。
問題発生の経緯
前提
Mysqlサーバのバックアップについて以下の4つの方法を利用しており、
基本的には作業手順としては、2系統以上ではバックアップを取得して何かあった時に問題なく復元できるようにしている。
・ MyDumper/MyLoaderを利用したバックアップ
・ XtraBackupを利用したバックアップ
・ Mysqlサーバのコールドバックアップ
・ xfsdumpを利用したファイルシステムダンプを利用したバックアップ
またパフォーマンス対応の為、Mysqlデータ領域とMysqlのredoログ領域を分離して管理しており、
innodb_flush_log_at_trx_commit=2でファイルキャッシュに出力している。
今回トラブルが発生したのはxfsdumpを利用したバックアップ。
大容量データを扱っている関係で、慢性的にデータ容量不足であったことと、パフォーマンス対応の為、複数領域に分けてMysqlサーバのデータを管理していた。
/var/lib/mysql ・・・ Mysqlデータディレクトリ
/var/lib/mysql-bin ・・・ バイナリログ、Redo ログファイルへのディレクトリパス領域
/var/lib/mysql-tablespace ・・・ 退避用テーブルスペース
datadir = /var/lib/mysql ・・・ Mysqlデータディレクトリ
log-bin = /var/lib/mysql-bin/mysql-bin.index ・・・ バイナリログ、Redo ログファイルへのディレクトリパス領域
innodb_log_group_home_dir = /var/lib/mysql-bin/ ・・・ バイナリログ、Redo ログファイルへのディレクトリパス領域
問題が発生した経緯
本来ならば以下の手順でバックアップを取得すべきだったが、今回誤ってMysqlサーバを停止せずにxfs_freezeを行った上、redoログ領域のfreezeを先に解除してしまった事で単純復旧できなくなった。
本来やるべき作業手順（この通りやってれば問題なかったはず。。。
# 1. Mysql Serverを停止する
systemctl stop mysql
# 2. XFSを停止する
xfs_freeze -f /var/lib/mysql
xfs_freeze -f /var/lib/mysql-bin
xfs_freeze -f /var/lib/mysql-tablespace
# 3. XFSをダンプする
xfsdump - /var/lib/mysql | pigz > /opt/backup/var_lib_mysql_20200624.dump.gz
xfsdump - /var/lib/mysql-bin | pigz > /opt/backup/var_lib_mysql-bin_20200624.dump.gz
xfsdump - /var/lib/mysql-tablespace | pigz > /opt/backup/var_lib_mysql-tablespace_20200624.dump.gz
# 4. XFSを停止を解除する
xfs_freeze -u /var/lib/mysql
xfs_freeze -u /var/lib/mysql-bin
xfs_freeze -u /var/lib/mysql-tablespace
# 5. Mysql Serverを起動する
systemctl start mysql
作業経緯
Mysql Serverを起動しっぱなしで、xfs_freezeを行った際に、/var/lib/mysql-binと/var/lib/mysql-tablespaceはさくっとバックアップが完了したのだが、データ領域の/var/lib/mysqlはデータ量が多い為バックアップがなかなか終わらなかった。
2020-06-24T05:25:17.678632+09:00 0 [Warning] InnoDB: A long semaphore wait:
この時点で、監視システムからMysqlサーバがダウンしたとアラートが発生し、調査をするとセマフォロックがかかっていることが分かった為、一旦/var/lib/mysqlへのダンプを止めてしまった。
で再実行したのだが、その際に、xfs_freezeを行わずに、xfsdumpを行ったため、データ領域とredoログ領域のデータがずれることになった。
その後、復旧作業を行ったのだが、
unpigz --stdout /opt/backup/var_lib_mysql_20200624.dump.gz | xfsrestore - /var/lib/mysql
unpigz --stdout /opt/backup/var_lib_mysql-bin_20200624.dump.gz | xfsrestore - /var/lib/mysql-bin
unpigz --stdout /opt/backup/var_lib_mysql-tablespace_20200624.dump.gz | xfsrestore - /var/lib/mysql-tablespace
Mysqlサーバを起動すると以下のようなエラーが出るようになった。
2020-06-26T01:51:56.999337+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=7] log sequence number 7544572483711 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:56.999374+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.000535+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=2] log sequence number 7544572485197 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.000549+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.026524+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=5] log sequence number 7544572484325 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.026540+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.026697+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=6] log sequence number 7544572485308 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.026707+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.026849+09:00 0 [ERROR] InnoDB: Page [page id: space=0, page number=57] log sequence number 7544572485308 is in the future! Current system log sequence number 7544572483701.
2020-06-26T01:51:57.026857+09:00 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.
2020-06-26T01:51:57.273586+09:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDBログシーケンス番号(LSN)を進める方法
InnoDB: Page [page id: space=0, page number=57] log sequence number 7544572485308 is in the future! Current system log sequence number 7544572483701.
というわけで
7544572483701-7544572485308 = 1607
ということで、1607ほど未来のLSNになっている。
現在のログ位置が未来の場合、今の位置に超えたページに対してシャットダウンリカバリを実行しないとのことなので、 今回のケースの場合、最新版のLSNとエラーの出ているLSNの間に必要とされるトランザクションが一切ない為、トランザクションを発行してLSNを進める事で対応した。
※未知なトラブルがあるかも知れないので、やるとしても自己責任で行ってください。
#!/bin/sh
mysql -uroot --password='パスワード' -e 'SHOW ENGINE INNODB STATUS;' | sed 's/\\n/\n/g' | grep "^Log sequence";
mysql -uroot --password='パスワード' test <<EOF
DROP TABLE IF EXISTS temp_advance_lsn;
CREATE TABLE temp_advance_lsn (col1 text) ENGINE=InnoDB;
INSERT INTO temp_advance_lsn VALUES (REPEAT('0123456789' , 1000));
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
INSERT INTO temp_advance_lsn SELECT * FROM dev_takagi.temp_advance_lsn;
DROP TABLE temp_advance_lsn;
EOF
mysql -uroot --password='パスワード' -e 'SHOW ENGINE INNODB STATUS;' | sed 's/\\n/\n/g' | grep "^Log sequence";
実行結果はこんな感じ、実行前後でLSNが10,794,127ほど増えている。
# /var/lib/mysql/LSN.sh
mysql: [Warning] Using a password on the command line interface can be insecure.
Log sequence number 7544572489981
mysql: [Warning] Using a password on the command line interface can be insecure.
mysql: [Warning] Using a password on the command line interface can be insecure.
Log sequence number 7544583284108
少しだけ不安が残るが、この処理を行った後、Mysqlサーバを再起動したところ、エラーは発生しなくなった。