MySQL で行ベースレプリケーションしていて、特定の操作を行ったときにレプリケーションがエラーで止まる事象が発生しました。
そのときの調査のログや対応の方法のメモ。
原因調査
まず、レプリケーションのスレーブでレプリケーションの状態を見ました。
mysql -e 'show slave status \G'
以下は抜粋です。
Master_Log_File: binlog.000225
Read_Master_Log_Pos: 42626469
Relay_Master_Log_File: binlog.000216
Slave_IO_Running: Yes
Slave_SQL_Running: No
Exec_Master_Log_Pos: 66177326
Last_SQL_Errno: 1032
Last_SQL_Error: Could not execute Delete_rows event on table ore_db.ore_category; Can't find record in 'ore_category', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log binlog.000216, end_log_pos 66178214
ore_category というテーブルの Delete_rows イベントを実行しようとしたところ HA_ERR_KEY_NOT_FOUND となったようです。要するに削除しようとしたレコードが存在しなかったということです。
また、スレーブのエラーログには下記が記録されていました（見やすくするために適当に改行を入れています）。
[ERROR] [MY-010584] [Repl] Slave SQL for channel '': Could not execute Delete_rows event on table ore_db.ore_category;
Can't find record in 'ore_category', Error_code: 1032;
handler error HA_ERR_KEY_NOT_FOUND; the event's master log binlog.000216, end_log_pos 66178214, Error_code: MY-001032
[Warning] [MY-010584] [Repl] Slave: Can't find record in 'ore_category' Error_code: MY-001032
[ERROR] [MY-010586] [Repl] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START".
We stoppedat log 'binlog.000216' position 66177326
マスターのバイナリログ binlog.000216 の 66178214 でエラーになったためレプリケーションが 66177326 で止まっている、とのことです。
この情報を頼りにバイナリログから原因のクエリを特定します。
mysqlbinlog binlog.000216 --base64-output=decode-rows -vv -j 66177326 --stop-position=66178214 > binlog.000216.sql
エラーでコケたトランザクションのクエリが表示されます。原因となるクエリは下記でした。
### DELETE FROM `ore_db`.`ore_list` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=1 is_null=0 */ ### @2='' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @3=900 /* SHORTINT meta=0 nullable=1 is_null=0 */ ### @4='2019-09-17 10:26:10' /* DATETIME(0) meta=0 nullable=1 is_null=0 */ ### DELETE FROM `ore_db`.`ore_category` ### WHERE ### @1=1 /* LONGINT meta=0 nullable=1 is_null=0 */ ### @2=1 /* LONGINT meta=0 nullable=1 is_null=0 */ ### @3='oreore' /* VARSTRING(1020) meta=1020 nullable=1 is_null=0 */ ### @4=NULL /* LONGINT meta=0 nullable=1 is_null=1 */
このスレーブの ore_category を見てみたところ ore_list も ore_category も上記のクエリに該当する行は存在していました。
ore_category には FOREIGN KEY (ore_list_id) REFERENCES ore_list (ore_list_id) ON DELETE CASCADE ON UPDATE CASCADE のような外部キー制約があって ore_list が削除されると ON DELETE CASCADE によって一緒に消えます。
どうやら、外部キー制約の ON DELETE CASCADE によって消えたはずの ore_category をさらに削除しようとしてエラーになったっぽいです。
適当なテーブルを作って試行錯誤してみたところ 外部キー制約の ON DELETE CASCADE によって削除された行はバイナリログに書かれない ことがわかりました。
つまりこのケースだと ore_category の削除がバイナリログに記録されるはずありません（ore_list の削除の時点で ore_category は消えてるので削除する方法がない（クエリを実行しても対象行がなければ行ベースのバイナリログには記録されない））。
これは MySQL のバグ臭い・・・と思って調べると下記が見つかりました。
multi-table DELETE ？
うーん Laravel の Eloquent 使っているのでそんなクエリは無いと思うのだけど・・・・
DELETE L, E, C, A FROM ore_latest L LEFT JOIN ore_list E ON E.ore_list_id = L.ore_list_id LEFT JOIN ore_category C ON C.ore_list_id = E.ore_list_id LEFT JOIN ore_article A ON A.article_id = C.article_id WHERE L.ore_latest_id = ?
普通にあったわ。記憶にあるような無いような・・・
復旧方法
MySQL でレプリケーションが止まったときの復旧方法といえば、かつては手作業でマスター・スレーブ間の整合をとって SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1 でステートメントをスキップする、とかでしたが、GTID レプリケーションしてたのでこの方法は使えません。
GTID レプリケーションの場合は原因となっている GTID を特定してスレーブでその GTID を空のトランザクションで上書きする、みたいな方法が使えるのですが、今回のケースだと ore_category の削除が誤ってバイナリログに書かれてしまっているだけなので HA_ERR_KEY_NOT_FOUND のエラーだけ無視してしまえば OK です。
slave_skip_errors パラメータを使えば特定のエラーだけ無視させることができるのですが、今回のケースなら slave_exec_mode を IDEMPOTENT にしてしまえばこのエラーは無視できます。
ので、原因の multi-table DELETE を個別の DELETE になるように修正した上で、下記の手順でレプリケーションを復旧させました。
set global slave_exec_mode = 'IDEMPOTENT'; show variables like 'slave_exec_mode'; /* IDEMPOTENT になっている */ start slave; show slave status \G /* Read_Master_Log_Pos と Exec_Master_Log_Pos が一致することを確認 */ /* Slave_SQL_Running が Yes */ /* Last_Error は記録されていない */ set global slave_exec_mode = 'STRICT'; show variables like 'slave_exec_mode'; /* STRICT になっている */
さいごに
この MySQL のバグは Verified なのでまだ修正されていないもよう。とりあえず行ベースレプリケーションしてるなら multi-table DELETE は使ったらダメ。
あと slave_exec_mode = IDEMPOTENT はそれほど害はないと思うし NDB ストレージエンジン（MySQL Cluster）だとこっちがデフォルトらしいので、もう slave_exec_mode = IDEMPOTENT で運用しでもいいんじゃないかと思った。
