MySQL のバージョンアップによる MHA のバグを踏んだ話 [DeNA インフラ SRE]

こんにちは、IT 基盤部の西崎です。主に DeNA がグローバルに展開するゲームのインフラ管理を担当しています。

今回は MySQL のバージョンアップによって社内で利用しているツールで障害が発生し、その調査をした時のことをまとめてみます。細かい話になりますが、大規模に MySQL を使っている環境ならではの経験を紹介できると思います。

この調査自体は数年前に行ったものなので、この後の対応などについても追って記事にできればと考えています。

何が起こったのか

DeNA では MHA という MySQL の高可用性ツールを利用しています。

詳細は他に譲りますが、MySQL のレプリケーション構成において master インスタンスが故障した場合でも、最小限のダウンタイムとデータロスのみで正しいレプリケーション構成を復旧させることのできるツールです。

今回は MySQL 5.7.9 で mysqlbinlog に入った修正に MHA が追従できておらず、特定の条件で master 障害時のフェイルオーバーがエラーになる状況になっており、本番環境で実際にこのエラーが発生してしまったことを紹介します。¹

MySQL の変更内容

分かりやすさのため、ここからは原因 -> 結果の順序で説明していきます。

障害の原因は、2015年にリリースされた MySQL 5.7.9 で mysqlbinlog の動作が変わったことでした。（mysqlbinlog はバイナリファイルである binlog を人が読める形に出力する MySQL 付属のユーティリティツールです）

Changelog の以下が該当の箇所です。

Replication: mysqlbinlog printed a ROLLBACK statement at the end of the binary log file, which when played back failed with error 1782 @@SESSION.
GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.
This occurred when the binary log file did not include any data related events, or when the relay log file included a Format_description_log_event that had been generated on the master at server startup.

The fix for this issue causes a relay log's Format_description_log_event to do nothing if it is applied by a BINLOG statement, and stops a ROLLBACK from setting gtid_next to ANONYMOUS when the state of gtid_next has not yet been determined by a subsequent event. (Bug #76887, Bug #20980932)

具体的には「GTID_MODE を有効にした際に relaylog を mysqlbinlog に読ませるとエラーになることがある」というバグを修正するため、「mysqlbinlog は relaylog に記載された slave サーバのメタデータ（Format_description_event）を読み込んでも何もしない（relaylog の Format_description_event の場合、その内容を出力せず return する）」ようになったと理解しています。

修正が行われた PR のリンク
- 今回直接関係しているのは追加された以下のコードです

  if (is_relay_log_event())
  {
    my_b_printf(head, "# This Format_description_event appears in a relay log "
                "and was generated by the slave thread.\n");
    DBUG_VOID_RETURN;
  }

Format_description_event とは

MySQL の binlog の最初に記載される、binlog のメタデータのことです（以下 FDE と略記します）。

binlog は「イベント」という単位で UPDATE や DELETE などのデータ更新を記録していますが、FDE はその中でも MySQL のバージョン情報などを記した特殊なイベントです。

自分もこの調査で初めて知ったのですが、 MySQL や mysqlbinlog は最初にこの FDE を見て、その binlog を読み取る際に必要な情報を得ているようです。

詳説：binlog を読んでみる

イメージを持ちやすくするため、実際の binlog がどのように書かれているのかを紹介します。

細かい部分になるため特に興味がなければ読み飛ばして下さい。 binlog が mysqlbinlog によって人が読めるものになるイメージが掴めれば本記事の意図としては十分です。

binlog はその名の通りバイナリファイルです。例として、テスト用に構築した MySQL(5.7.25) の binlog の冒頭を hexdump で出力すると以下のようになります。

ubuntu@test-db-1:~$ sudo hexdump -C  /var/lib/mysql/mysql-bin.000002 | head -n 5
00000000  fe 62 69 6e c0 63 f7 69  0f 01 00 00 00 77 00 00  |.bin.c.i.....w..|
00000010  00 7b 00 00 00 01 00 04  00 35 2e 37 2e 32 35 2d  |.{.......5.7.25-|
00000020  6c 6f 67 00 00 00 00 00  00 00 00 00 00 00 00 00  |log.............|
00000030  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000040  00 00 00 00 00 00 00 00  00 00 00 c0 63 f7 69 13  |............c.i.|

ぱっと見では分かりませんが、以下のリファレンスを見ることで読み解くことができます。

MySQL: Replication Protocol
- binlog の冒頭は「0xFE ‘bin’」という特定の Binlog File Header が記載されます。その後に各種イベントが記載されます
MySQL: Binlog Event
- MySQL 5.0.0 以降の場合、最初のイベントは常に FDE です
- 全てのイベントの最初には共通ヘッダが付きます（ページ最下部の「Binlog Event Header」）

上記の情報から、今回のバージョン（MySQL 5.7.25）の binlog の冒頭は「Binlog File Header(固定文字列) -> FDE のヘッダ（全てのイベントに共通のヘッダ）-> FDE の内容 ->（次のイベントへ…）」の形になっているはずです。

それでは実際に読んでみましょう。

ubuntu@test-db-1:~$ sudo hexdump -C  /var/lib/mysql/mysql-bin.000002 | head -n 5
00000000  [fe 62 69 6e]    [c0 63 f7 69]        [0f]          [01 00 00 00] [77 00 00  |.binLd.i.....w..|
    （Binlog File Header）  (timestamp)   (FDE のイベントタイプ)    (サーバID)   (イベントサイズ)
00000010  00] [7b 00 00 00]   [01 00]     [04 00]        [35 2e 37 2e 32 35 2d  |.{.......5.7.25-|
            (次のイベントの位置) (フラグ) (binlog バージョン)  
00000020  6c 6f 67 00 00 00 00 00  00 00 00 00 00 00 00 00  |log.............|
00000030  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000040  00 00 00 00 00 00 00 00  00 00 00]      [c0 63 f7 69]               13  |...........Ld.i.|
              (MySQL バージョン)                 (create-timestamp)

先頭から順に整理すると以下になります。 timestamp など数値の部分はリトルエンディアンです。

Binlog File Header：

内容	説明	16進数の値	意味
Binlog File Header	binlog 冒頭の固定値	fe 62 69 6e	0xFE ‘bin’

共通ヘッダ：

Type	Name	Description	16進数の値	意味
int<4>	timestamp	seconds since unix epoch	c0 63 f7 69	1777820608 (Unix time)
int<1>	event_type	See mysql::binlog::event::Log_event_type	0f	0f → 15 は FDE の番号
int<4>	server-id	server-id of the originating mysql-server. Used to filter out events in circular replication	01 00 00 00	1
int<4>	event-size	size of the event (header, post-header, body)	77 00 00 00	119
int<4>	log-pos	position of the next event	7b 00 00 00	123
int<2>	flags	See Binlog Event Header Flags	01 00	1 -> 現在書き込み中というフラグ

共通ヘッダの後に続く FDE の内容：

Type	Name	Description	16進数の値	意味
int<4>	binlog-version	Version of the binlog format. See Binlog Version	04 00	Binlog v4
string[50]	mysql-server version	version of the MySQL Server that created the binlog. The string is evaluated to apply workarounds on the slave.	35 2e 37 2e 32 35 2d 6c 6f 67	‘5.7.25-log’
int<4>	create-timestamp	seconds since Unix epoch when the binlog was created	c0 63 f7 69	1777820608 (Unix time)

（Description までは上記リンクの内容をそのまま記載しています）

mysqlbinlog で binlog を読む

上記の binlog を mysqlbinlog で出力すると以下になります。 # at 4 から始まるのが FDE（Start: binlog v 4 と記載）で、その下に # at 123 という部分に Previous-GTIDs というイベントが書かれています。

ubuntu@test-db-1:~$ sudo mysqlbinlog /var/lib/mysql/mysql-bin.000002
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;

# at 4
#260503 15:03:28 server id 1  end_log_pos 123 CRC32 0xfcc8d454 	Start: binlog v 4, server v 5.7.25-log created 260503 15:03:28 at startup
# Warning: this binlog is either in use or was not closed properly.
ROLLBACK/*!*/;
BINLOG '
wGP3aQ8BAAAAdwAAAHsAAAABAAQANS43LjI1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAADAY/dpEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AVTUyPw=
'/*!*/;

# at 123
#260503 15:03:28 server id 1  end_log_pos 154 CRC32 0x4efc58a0 	Previous-GTIDs

バイナリより読みやすい形で binlog の中身が出力されることが分かります。また今回は省いていますが、この下に実際のデータの UPDATE などの変更内容が同様にイベントの形で記載されていきます。

このように binlog はイベントという単位で情報を書き出しており、mysqlbinlog を使うと binlog の内容を読むことができます。

mysqlbinlog に修正が入った

mysqlbinlog は MHA の中でも利用されていますが、今回原因になった MySQL 5.7.9 の修正では mysqlbinlog の挙動が変わりました。「mysqlbinlog は relaylog に記載された slave サーバのメタデータ（Format_description_event）を読み込んでも何もしない」ようになったのです。

先ほどは binlog の例でしたが、実は relaylog の場合、FDE が最初に2回出力されます。これは relaylog が master の binlog を slave が受け取ったものであることに起因します。 slave サーバが relaylog を作成する時に FDE を書き出した後、master サーバの binlog に書かれていた master サーバの FDE が転送されてくるためです。

以下が実際の relaylog の内容です。（上記のサーバID 1 のインスタンスの binlog をサーバID 2 のインスタンスが受け取ったものです）

0f という FDE を表すイベントタイプが2回出てきており、FDE が2つあることが分かります。そして2つの FDE ではサーバID とフラグの内容が違います。最初の FDE はサーバID が 2 で、Flag も 0x40（ LOG_EVENT_RELAY_LOG_F ）なので、slave が relaylog に書き込んだイベントです。

ubuntu@test-db-2:~$ sudo hexdump -C /var/lib/mysql/test-db-2-relay-bin.000005
00000000  [fe 62 69 6e] [d9 8b f7 69]   [0f]          [02 00 00 00] [77 00 00  |.bin...i.....w..|
                                 （FDE のイベントタイプ） (server-id)
00000010  00] [7b 00 00 00] [40 00] [04  00] 35 2e 37 2e 32 35 2d  |.{...@...5.7.25-|
                       (1つ目の FDE の flag)
00000020  6c 6f 67 00 00 00 00 00  00 00 00 00 00 00 00 00  |log.............|
00000030  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  |................|
00000040  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 13  |................|
00000050  38 0d 00 08 00 12 00 04  04 04 04 12 00 00 5f 00  |8............._.|
00000060  04 1a 08 00 00 00 08 08  08 02 00 00 00 0a 0a 0a  |................|
00000070  2a 2a 00 12 34 00 01 5b  3f a8 14 d9 8b f7 69 23  |**..4..[?.....i#|
00000080  02 00 00 00 1f 00 00 00  9a 00 00 00 c0 00 00 00  |................|
00000090  00 00 00 00 00 00 f7 a6  a7 57 00 00 00 00 04 01  |.........W......|
000000a0  00 00 00 2f 00 00 00 00  00 00 00 20 00 1b 03 00  |.../....... ....|
000000b0  00 00 00 00 00 6d 79 73  71 6c 2d 62 69 6e 2e 30  |.....mysql-bin.0|
000000c0  30 30 30 30 32 6c 12 3e  1b [c0 63 f7 69] [0f]            [01 00  |00002l.>..c.i...|
                                               （FDE のイベントタイプ） (server-id)
000000d0  00 00] [77 00 00 00] [00 00  00 00]   [00 00]   [04 00] [35 2e  |..w...........5.|
                                         (2つ目の FDE の flag)
000000e0  37 2e 32 35 2d 6c 6f 67  00 00 00 00 00 00 00 00  |7.25-log........|

mysqlbinlog で同じ relaylog を読むとやはり FDE（Start: binlog v 4 と記載されているイベント）が2回出力されます。そして最初の FDE 部分のコメントから、mysqlbinlog が master と slave の FDE を見分けていることが分かります。結果として FDE の中身を出力した BINLOG セクションは2つ目の FDE でしか出力されていません。

ubuntu@test-db-2:~$ sudo mysqlbinlog /var/lib/mysql/test-db-2-relay-bin.000005
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;

# at 4
#260503 17:54:33 server id 2  end_log_pos 123 CRC32 0x14a83f5b 	Start: binlog v 4, server v 5.7.25-log created 260503 17:54:33
# This Format_description_event appears in a relay log and was generated by the slave thread.

# at 123
#260503 17:54:33 server id 2  end_log_pos 154 CRC32 0x57a7a6f7 	Previous-GTIDs
# [empty]

# at 154
#700101  0:00:00 server id 1  end_log_pos 0 CRC32 0x1b3e126c 	Rotate to mysql-bin.000002  pos: 795

# at 201
#260503 15:03:28 server id 1  end_log_pos 0 CRC32 0xc1921f14 	Start: binlog v 4, server v 5.7.25-log created 260503 15:03:28
BINLOG '
wGP3aQ8BAAAAdwAAAAAAAAAAAAQANS43LjI1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
ARQfksE=
'/*!*/;

ところが全く同じ relaylog を MySQL 5.7.8 の mysqlbinlog で読むと、以下のように 1つ目の FDE でも Binlog セクションが出力されます。 MySQL 5.7.9 以降、mysqlbinlog が relaylog の最初の FDE を無視するようになったことが確認できます。

ubuntu@test-db-2:~$ sudo mysql-5.7.8-rc-linux-glibc2.5-x86_64/bin/mysqlbinlog /var/lib/mysql/test-db-2-relay-bin.000005
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;

# at 4
#260503 17:54:33 server id 2  end_log_pos 123 CRC32 0x14a83f5b 	Start: binlog v 4, server v 5.7.25-log created 260503 17:54:33
BINLOG '
2Yv3aQ8CAAAAdwAAAHsAAABAAAQANS43LjI1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
AVs/qBQ=
'/*!*/;

# at 123
#260503 17:54:33 server id 2  end_log_pos 154 CRC32 0x57a7a6f7 	Previous-GTIDs
# [empty]

# at 154
#700101  0:00:00 server id 1  end_log_pos 0 CRC32 0x1b3e126c 	Rotate to mysql-bin.000002  pos: 795

# at 201
#260503 15:03:28 server id 1  end_log_pos 0 CRC32 0xc1921f14 	Start: binlog v 4, server v 5.7.25-log created 260503 15:03:28
BINLOG '
wGP3aQ8BAAAAdwAAAAAAAAAAAAQANS43LjI1LWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXwAEGggAAAAICAgCAAAACgoKKioAEjQA
ARQfksE=
'/*!*/;

MHA は最初の FDE しか見ない

しかし MHA は relaylog の 2つの FDE のうち、最初の FDE しか見ない実装になっていました。以下は MHA がフェイルオーバーの際に、どのように binlog と relaylog を利用して slave のデータを最新化するかを示しています。

MHA データ最新化の仕組み — 出典：https://www.slideshare.net/matsunobu/mha-for-mysqldena

MHA は master サーバが故障した場合、図のように以下のログを切り貼りしたものを mysqlbinlog を通して MySQL に適用することでデータ復旧を行います。

i1
- slave に転送されているが、実行されていない relaylog（トランザクションの途中で途切れたものなど）
i2
- ある slave には転送されているが、別の slave には転送されていない relaylog
X
- 旧 master に残っているが、どの slave にも転送されていない binlog

貼り付けられる順番は i1 → i2 → X のため、結合が行われる場合は必ず relaylog が先頭にきます。そして MHA は最初のファイルの一番目の FDE のみ切り出す実装のため、本来必要な master FDE を利用できません。

この結果、mysqlbinlog がデータ更新イベントを読み込んだ際に「まだ必要なメタデータ（FDE）を読み込んでいない」判定となりエラーになってしまいます。

ただし i1 や i2 が発生するには master -> slave の binlog 転送中の特定のタイミングで master が突然処理を止める必要があり、実際にこの切り貼り作業が MHA によって行われる頻度は高くありません。それだけに、この事象の発見が遅れたとも言えます。

本番環境でエラー発生

長らく気づかれずにいたこのバグ（MySQL バージョンへの不追従）ですが、ついに本番環境で発生しました。

あるグローバル向けゲームのイベント当日、シャーディングやレプリケーションで分散した後でも１インスタンス当たり 1000 rps 近い負荷が掛かっている状況。そんな中、1台の master インスタンスがホスト故障で停止しました。

普段通り MHA が自動 Failover を行って障害なくサービス提供を続けることができましたが、元々3台いた slave のうち1台がレプリケーションでエラーを起こし、最新データに追従できなくなりました。調べてみると MHA によるデータ最新化の際に、上記の理由で不正になった relaylog を読み込めずにエラーになっていました。

ERROR: malformed binlog: it does not contain any Format_description_log_event.
I now found a Update_rows event, which is not safe to process without a Format_description_log_event.

このインスタンスのみ旧 master からの最新データを受け取ることができず、結果としてその後のレプリケーションで受け取る（新 master からの）relaylog でもデータ不整合を起こしてデータを更新できない状況でした。幸いにして他のインスタンスでは発生しなかったため、このインスタンスをサービスから外すことで本番環境への影響は抑えられました。

発生条件と影響

本エラーは特定の slave インスタンスが以下の条件を満たしたときに発生します。

MySQL バージョンが 5.7.9 以上
MHA によるフェイルオーバー発生時に、以下の条件のどちらかを満たす
- 自身よりも旧 master binlog 読み込み（Read_Master_Log_Pos）が進んでいる他の slave がいる
- 旧 master から受け取ったが未実行の relaylog がある（Read_Master_Log_Pos と Exec_Master_Log_Pos が異なっている）

条件を満たすと以下の影響があります。

条件を満たした該当 slave へのデータ最新化が失敗する

ただし条件 2. がそれなりの負荷を受けている状態でないと発生せず、私たちの環境でも一度しか発生していません。

まとめ

細かい話になってしまいましたが、一言で言うと MySQL 5.7.9 で mysqlbinlog に入った修正に MHA が追従できておらず、特定条件下でフェイルオーバー時のデータの最新化に失敗しました。

再現にはそれなりの負荷が掛かっている最中に master サーバがホスト故障などで急に応答しなくなる必要があり、私たちの環境でもこの1回しか発生していません。あまり頻発するものではないと思いますが、もし MHA を利用されていたり、MySQL のレプリケーション周りの挙動が気になる方がいれば参考にして頂けたら嬉しいです。

今回は大規模に MySQL を利用しているとこのような事象にも遭遇するのだという学びがありました。また本ブログでは時系列順に記載していますが、実際の調査では本番環境で発生したデータ不整合から MHA のソースコード、さらに MySQL のソースコードや binlog の仕様まで遡って調べる必要があり、非常に大変なものでした。しかしこれまで知らなかった MySQL と MHA の深い部分を探検することができ、とても面白い調査ができたと思います。

本記事では主に MySQL 5.7 を扱っていること、引用する MHA の資料に合わせられることから master / slave の表記を用いています ↩︎