環境
- MacBook Pro, macOS: Ventura 13.3.1 (a)
- zsh のバージョン: 5.9
- Bundler のバージョン: 2.4.13
- データベース: MariaDB (ver 10.6.13)
起こったトラブルの内容
- MariaDB のサーバーを
stopすることができない. しかも,statusで PID ファイルの存在が言及されているのに,stopでは PID ファイルが見つからないと言われている.
% mysql.server start
Starting MySQL
SUCCESS!
% mysql.server stop
ERROR! MySQL server PID file could not be found!
% mysql.server status
ERROR! MariaDB is not running, but PID file exists
- その状態で一度再起動をしてしまうと, 今度は立ち上がりすらしなくなってしまう.
% mysql.server start
Starting MariaDB
.230522 18:25:18 mysqld_safe Logging to '/usr/local/var/mysql/(comp name).local.err'.
230522 18:25:18 mysqld_safe Starting mariadbd daemon with databases from /usr/local/var/mysql
/usr/local/opt/mariadb@10.6/bin/mysql.server: line 264: kill: (1005) - No such process
ERROR!
解決のためにやったこと
その 1: アンインストール, 再インストール
まず, MariaDB 関連ファイルである /usr/local/var/mysql と /usr/local/etc/my.cnf (で始まるファイル) を rm コマンドで削除し, MariaDB は brew 経由でアンインストールしました.
% rm -rf /usr/local/var/mysql
% rm -rf /usr/local/etc/my.cnf*
% brew uninstall mariadb@10.6
Uninstalling /usr/local/Cellar/mariadb@10.6/10.6.13... (917 files, 186.3MB)
そして, brew 経由で再び version 10.6 の MariaDB をインストールしました.
% brew install mariadb@10.6
==> Downloading https://formulae.brew.sh/api/formula.jws.json
########################################################################################### 100.0%
==> Fetching mariadb@10.6
(略)
==> Summary
🍺 /usr/local/Cellar/mariadb@10.6/10.6.13: 917 files, 186.3MB
==> Running `brew cleanup mariadb@10.6`...
Disable this behaviour by setting HOMEBREW_NO_INSTALL_CLEANUP.
Hide these hints with HOMEBREW_NO_ENV_HINTS (see `man brew`).
再インストールをした後, mysql サーバーの立ち上げを試みました.
% mysql.server start
Starting MariaDB
230522 16:40:45 mysqld_safe Logging to '/usr/local/var/mysql/(comp name).local.err'.
230522 16:40:46 mysqld_safe A mysqld process already exists
SUCCESS!
% mysql.server status
ERROR! MariaDB is not running
すると, start では起動はするものの, status で確認しようとしても, 起動していないと返されてしまいました.
その2: 自動立ち上げの拒否
PID ファイルが存在するのに見つからない問題については, ps コマンドで起動している MariaDB 関連のプログラムを見てみると, 以下のようになりました.
% ps aux | grep mysql
(name) 9163 0.0 0.4 34647908 69868 ?? S 4:38PM 0:00.67 /usr/local/opt/mariadb@10.6/bin/mariadbd --basedir=/usr/local/opt/mariadb@10.6 --datadir=/usr/local/var/mysql --plugin-dir=/usr/local/opt/mariadb@10.6/lib/plugin --log-error=/usr/local/var/mysql/(comp name).local.err --pid-file=(comp name).local.pid
(name) 9092 0.0 0.0 34134040 1224 ?? S 4:37PM 0:00.02 /bin/sh /usr/local/opt/mariadb@10.6/bin/mysqld_safe --datadir=/usr/local/var/mysql
(name) 9783 0.0 0.0 34121332 628 s001 R+ 5:26PM 0:00.00 grep mysql
よって, 実際にはサーバーは立ち上がってはいるが, mysql 側だとそれのを検知できていないということがわかりました.
そして, 動いているプロセスを kill したところ, 即座にサーバーが復活してしまいました.
% kill -9 9163
% ps aux | grep mysql
(name) 9903 0.0 0.0 34121332 628 s001 R+ 5:30PM 0:00.00 grep mysql
(name) 9894 0.0 0.4 34646932 67156 ?? S 5:29PM 0:00.09 /usr/local/opt/mariadb@10.6/bin/mariadbd --basedir=/usr/local/opt/mariadb@10.6 --datadir=/usr/local/var/mysql --plugin-dir=/usr/local/opt/mariadb@10.6/lib/plugin --log-error=/usr/local/var/mysql/(comp name).local.err --pid-file=(comp name).local.pid
(name) 9824 0.0 0.0 34124824 1348 ?? S 5:29PM 0:00.02 /bin/sh /usr/local/opt/mariadb@10.6/bin/mysqld_safe --datadir=/usr/local/var/mysql
サーバーの再起動が起こってしまう原因はパッケージマネージャーとして使っていた brew の自動起動によるものでした.
% brew services list
Name Status User File
mariadb@10.6 started (name) ~/Library/LaunchAgents/homebrew.mxcl.mariadb@10.6.plist
brew から自動起動を停止させました.
% brew services stop mariadb@10.6
Stopping `mariadb@10.6`... (might take a while)
==> Successfully stopped `mariadb@10.6` (label: homebrew.mxcl.mariadb@10.6)
% brew services list
Name Status User File
mariadb@10.6 none
これにより, MariaDB が自動起動しないようになりました.
% mysql.server status
ERROR! MariaDB is not running
% ps aux | grep mysql
(name) 903 0.0 0.0 34130548 684 s001 S+ 6:23PM 0:00.00 grep mysql
その 3: redo ログ周辺を見る
エラーログを見てみたところ, 次のような記載がありました.
[Note] InnoDB: Starting crash recovery from checkpoint LSN=42628,42628
[ERROR] InnoDB: Missing FILE_CHECKPOINT at 42628 between the checkpoint 42628 and the end 42640.
そこで, MariaDB の crash recovery について調べてみたところ, 何かしらの原因でサーバーが立ち上がらない時, /usr/local/etc/my.cnf ファイルに
[mysqld]
innodb_force_recovery = 0 # 0 の部分には 0 以上 6 以下の整数が入る.
を追加することによって, MariaDB が Recovery モードで起動し, レベルに対応するリカバリーモードでの立ち上げになるということがわかりました.
なお, リカバリーモードのレベルが上がると, 強力になる分, データベースの破損が起こりうるので (具体的ににはレベル 5 から), やるとしたらレベル 1 1から順に 1 ずつ上げながらやっていくことに注意していください.
これを用いて, リカバリーモードで実行してみたところ, レベル 5 まではサーバーが起動せず, レベル 6 のみで起動しました.
そこで, リカバリーモードに関する公式レファレンス から各レベルでどのようなことを行っているのかを調べ, 原因を調査することにしました.
公式レファレンスに載っている各レベルの内容を大まかにみると, このようになっています (高レベルのものは低レベルのものを含んでいます).
| レベル | 内容 |
|---|---|
| 0 | (通常の起動) |
| 1 | ページに破壊があったとしても, サーバーの実行を継続する. |
| 2 | マスタースレッドの実行を停止する. |
| 3 | クラッシュリカバリ後に DML トランザクションのロールバックを行わないようにする. |
| 4 | クラッシュリカバリ後にトランザクションのロールバックを行わないようにする. |
| 5 | 不完全なトランザクションをコミットされたものと見なし, 起動時, undo ログを見ないようにする. |
| 6 | redo ログを見ないようにする. |
しかし, 立ち上げに成功した後, innodb_force_recovery レベル 0 に戻して status を確認したところ, MariaDB は動いていないが, PID ファイルはあると言われてしまい, 試しに, PID ファイルを削除し, もう一度 status で確認してみたところ, 今度は MariaDB は動いているが, PID ファイルがない 2 と言われてしまう状況に陥りました.
なお, これに関しては, 再インストールの時に my.cnf を適切な設定に戻していなかったためということになり, my.cnf に
[mysqld]
user = (name) # 追加
を追加してあげることにより, 正しい PID の PS 番号を返してくれるようになりました.
これとレベル 5 でサーバーが起動せず, レベル 6 でサーバーが起動したという状況も合わせて, redo ログに原因があるのではないかと考えました.
そして, redo ログは redo ログに関する公式レファレンス によると, ib_logfile0 にあるという記載があったので, ib_logfile0 を削除して, 実行してみたところ,
% mysql.server start
Starting MariaDB
.230526 14:26:56 mysqld_safe Logging to '/usr/local/var/mysql/(comp name).local.err'.
230526 14:26:56 mysqld_safe Starting mariadbd daemon with databases from /usr/local/var/mysql
SUCCESS!
% mysql.server status
SUCCESS! MariaDB running (19754)
% mysql.server stop
Shutting down MariaDB
. SUCCESS!
となり, サーバーの起動, 停止, ステータスの確認に成功しました.
最後に
初めての記事でしたが, ご覧いただきありがとうございました.
これからはトラブルシューティングの他にも色々な記事を書けて行けたらと思います.