MySQL の行ベースレプリケーションで multi delete するとレプリケーションが止まる件

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 のバグ臭い・・・と思って調べると下記が見つかりました。

• https://bugs.mysql.com/bug.php?id=94991
• https://bugs.mysql.com/bug.php?id=80821

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 で運用しでもいいんじゃないかと思った。