MariaDB のサーバーがおかしくなったので, 対処した話

# 環境

* 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 ファイルが見つからないと言われている.
```zsh
% 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
```
* その状態で一度再起動をしてしまうと, 今度は立ち上がりすらしなくなってしまう.
```zsh
% 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 経由でアンインストールしました.

```zsh
% 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 をインストールしました.
```zsh
% 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 サーバーの立ち上げを試みました.

```zsh
% 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 関連のプログラムを見てみると, 以下のようになりました.

``` zsh
 % 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 したところ, 即座にサーバーが復活してしまいました.

```zsh
% 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 から自動起動を停止させました.

```zsh
% 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 が自動起動しないようになりました.

```zsh
% 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 ログ周辺を見る

エラーログを見てみたところ, 次のような記載がありました.

```zsh
[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` ファイルに

```/usr/local/etc/my.cnf
[mysqld]
innodb_force_recovery = 0 # 0 の部分には 0 以上 6 以下の整数が入る.
```

を追加することによって, MariaDB が Recovery モードで起動し, レベルに対応するリカバリーモードでの立ち上げになるということがわかりました.

なお, リカバリーモードのレベルが上がると, 強力になる分, データベースの破損が起こりうるので (具体的ににはレベル 5 から), やるとしたらレベル 1 [^A]から順に 1 ずつ上げながらやっていくことに注意していください.

[^A]: レベル 0 は通常の起動であるため, レベル0で起動するのであるならば, この記事は必要ない.

これを用いて, リカバリーモードで実行してみたところ, レベル 5 まではサーバーが起動せず, レベル 6 のみで起動しました.

そこで, [リカバリーモードに関する公式レファレンス](https://mariadb.com/kb/en/innodb-recovery-modes/) から各レベルでどのようなことを行っているのかを調べ, 原因を調査することにしました.

公式レファレンスに載っている各レベルの内容を大まかにみると, このようになっています (高レベルのものは低レベルのものを含んでいます).

|レベル|内容|
|:---:|:---|
|0|(通常の起動)|
|1|ページに破壊があったとしても, サーバーの実行を継続する.|
|2|マスタースレッドの実行を停止する.|
|3|クラッシュリカバリ後に DML トランザクションのロールバックを行わないようにする.|
|4|クラッシュリカバリ後にトランザクションのロールバックを行わないようにする.|
|5|不完全なトランザクションをコミットされたものと見なし, 起動時, undo ログを見ないようにする.|
|6|redo ログを見ないようにする.|

------
しかし, 立ち上げに成功した後, `innodb_force_recovery` レベル 0 に戻して `status` を確認したところ, MariaDB は動いていないが, PID ファイルはあると言われてしまい, 試しに, PID ファイルを削除し, もう一度 `status` で確認してみたところ, 今度は MariaDB は動いているが, PID ファイルがない [^2] と言われてしまう状況に陥りました.

[^2]: こっちに関しては正しい反応

なお, これに関しては, 再インストールの時に `my.cnf` を適切な設定に戻していなかったためということになり, `my.cnf` に

```my.cnf
[mysqld]
user = (name) # 追加
```
を追加してあげることにより, 正しい PID の PS 番号を返してくれるようになりました.

------
これとレベル 5 でサーバーが起動せず, レベル 6 でサーバーが起動したという状況も合わせて, redo ログに原因があるのではないかと考えました.

そして, redo ログは [redo ログに関する公式レファレンス](https://dev.mysql.com/doc/refman/8.0/ja/innodb-redo-log.html) によると, `ib_logfile0` にあるという記載があったので, `ib_logfile0`　を削除して, 実行してみたところ,

```zsh
% 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!
```
となり, サーバーの起動,　停止,　ステータスの確認に成功しました.

# 最後に
初めての記事でしたが, ご覧いただきありがとうございました.

これからはトラブルシューティングの他にも色々な記事を書けて行けたらと思います.