ねぇアレクサ “InnoDB: Assertion failure” ってなに?「すみません、わかりませんでした。」

概要

フンフンフフーン…やばぁなんか mysql 起動しない。
ok google “InnoDB: Assertion failure”…

innodb_force_recovery = 1
innodb_force_recovery = 2
innodb_force_recovery = 3
innodb_force_recovery = 4

うわぁ、だめだぁああ

みたいな。

そんなとき。はたと気がついた。そうだ! Galera Cluster なのだった。今回は node1, node2 は正常 node3 がマッシヴな書き込みに耐えれなかった模様。しかもその犯人は自分というオチです。でも、簡単に窮地を脱する方法があります。

環境

Ubuntu 16.04
MariaDB Galera Cluster 10.1.36

事象

エラー内容は以下のような感じです。シングル構成の方は絶対に真似しないでください。また、作業前にバックアップをとりましょう。

# /etc/init.d/mysql restart
[....] Restarting mysql (via systemctl): mysql.serviceJob for mariadb.service failed because the control process exited with error code. See "systemctl status mariadb.service" and "journalctl -xe" for details.
failed!
# journalctl -xe
9月 15 01:49:22 node3 systemd[1]: mariadb.service: Failed with result 'exit-code'.
9月 15 01:49:30 node3 systemd[1]: Stopped MariaDB 10.1.36 database server.
-- Subject: Unit mariadb.service has finished shutting down
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mariadb.service has finished shutting down.
9月 15 01:49:30 node3 systemd[1]: Starting MariaDB 10.1.36 database server...
-- Subject: Unit mariadb.service has begun start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
--
-- Unit mariadb.service has begun starting up.
9月 15 01:49:32 node3 mysqld[3264]: WSREP: Failed to start mysqld for wsrep recovery: '2018-09-15 1:49:31 140009691633920 [Note] /usr/sbin/mysqld (mysqld 10.1.36-MariaDB-1~xenial) starting as process 3446 ...
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Using mutexes to ref count buffer pool pages
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: The InnoDB memory heap is disabled
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Compressed tables use zlib 1.2.8
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Using Linux native AIO
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Using generic crc32 instructions
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Initializing buffer pool, size = 256.0M
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Completed initialization of buffer pool
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Highest supported file format is Barracuda.
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Starting crash recovery from checkpoint LSN=801610394065
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 1:49:31 140009691633920 [Note] InnoDB: Starting final batch to recover 964 pages from redo log
9月 15 01:49:32 node3 mysqld[3264]: 2018-09-15 01:49:31 7f565a7fa700 InnoDB: Assertion failure in thread 140008862230272 in file log0recv.cc line 1172
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: Failing assertion: !page || (ibool)!!page_is_comp(page) == dict_table_is_comp(index->table)
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: We intentionally generate a memory trap.
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: If you get repeated assertion failures or crashes, even
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: immediately after the mysqld startup, there may be
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: corruption in the InnoDB tablespace. Please refer to
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
9月 15 01:49:32 node3 mysqld[3264]: InnoDB: about forcing recovery.
9月 15 01:49:32 node3 mysqld[3264]: 180915 1:49:31 [ERROR] mysqld got signal 6 ;

対処方法

クラスタなので、アイヤッ!じゃないエイヤッと全部データを削除して再起動しデータを同期しなおすこともできるわけです。クラスタで良かった。

# /etc/init.d/mysql stop
[ ok ] Stopping mysql (via systemctl): mysql.service.
# cp -Rip /var/lib/mysql/ /path/to/backup
# rm -rf `ls -d /var/lib/mysql/* | grep -v "/var/lib/mysql/mysql"`
# /etc/init.d/mysql start
[ ok ] Starting mysql (via systemctl): mysql.service.

トラブルシューティング

データ量が多いと、「systemd[1]: mariadb.service: Start operation timed out. Terminating.」のように systemctl によるサービス開始がタイムアウトしてしまうことがあります。
その様な場合は DefaultTimeoutStartSec の値を増やすことでサービス開始時のタイムアウト時間を延ばしてやることで対応が可能です。具体的な方法については既出の投稿をご参照ください。

スポンサーリンク