2019年7月26日金曜日

MySQLが刺さった時にざっと見るためのメモ

TL;DR

  • mysqldが 本当に 刺さって動作を停止している時のためのメモです。重いだけの時に使うものじゃない。
  • ざっと見る方法であって、解決方法じゃない。

まずは慌てず騒がずエラーログを見る。クラッシュしてるログが出てるならそれはそれでOK。mysqld_safe とか systemd を使っている場合、 mysqld が自動再起動されているかも知れない。クラッシュリカバリーの真っ最中はプロセスが浮いていても接続できないので、クラッシュリカバリー中だったら見守る。
OOM Killerに殺された場合はエラーログに何も出ずにsyslogだけ吐くので、 /var/log/messages あたりもチラ見しておくと吉。
特にクラッシュはしていないようであれば、 dstat でCPU使用率やDisk書き込み、IOPSあたりを見る。
Disk書き込み量やIOPSがガリガリ増えているなら、datadirにでもいって ls -ltr とかで更新がされてるかどうか見る。バイナリーログやInnoDBログが更新されているなら、刺さっててもまだ何かしている(=そのまま kill -9 でバッサリやると設定によってはファイルが壊れる)可能性がある。
設定によってはここでコアファイルをガリガリ書いている最中かも知れない。
その場合、ストレージ容量を食い破られないようにだけ注意(コアを吐き終わるまでmysqldが終了せず、コアは容量が足りなくて吐けず…でいつまでも終わらない)。
食い破られそうなら mysqldkill -9 で仕留めるしかない。
Diskが何も書いてなさげでCPUだけ回っているならバッファプール周りで何か起こっていそうな予感。体感ではチェンジバッファとかページクリーナーがぐるぐるしていることが多い。 poor man’s profiler やPercona Toolkit化された pt-pmp で見てもいいけど、見たところで多分幸せにはならない(解決方法はわからないから)
ただこのケースは kill -9 でも壊れる可能性は低い(体感)、ただしMyISAMとMroonga、オメーは別だ。
解析のためにコアファイルを取りたければ ulimit -c とかabrtdの設定を確認してから kill -6 。容量には注意。見かけ上のサイズにVSZ、実容量でRSSを取る。
Diskにも書いてないしCPUも回っていないことがまれにだがよくある(特に5.7でデカめのインスタンスに mysqladmin shutdown を放り投げたあと…)が、その場合はなんか変なところで刺さっているんだろう…コア取ったりpt-pmpでスタックトレースを送り付けた方がいいかも知れない。
復旧(InnoDBのみ、安全なパラメーター、クラッシュリカバリーが成功していればプロセスを起動するだけでもいい)させたら今度は中身を見ていく。バックアップや他のスレーブからデータをコピーしてくる場合、エラーログをどこかに残しておかないと追うことも出来なくなるので注意。
基本はエラーログ。綺麗に(?)クラッシュしてる場合は “mysqld got signal x” のログがあるはず。これが無くていきなりプロセスが消えている場合はOOM Killerに殺された可能性が高い。
06:37:30 UTC - mysqld got signal 6 ;
Dive into MySQL Error - Speaker Deck でしゃべったけれど、 “signal 6” はアサーション(主にInnoDB)、 “signal 11” はバグな傾向がある。
“This could be because you hit a bug.” って書いてあるけどこれは単なるハードコード文なので真に受けてはいけない。
再起動しようとしてまた “signal 6” で落ちるなら、InnoDBのデータが破損している気がする。エラーログに含まれるスタックトレースの中にinnobaseな関数が並んでたりすると更に確率が上がる。
何度起動しようとしても “signal 11” で落ち 続ける ならデータが壊れている && そのエラーハンドルにバグがある予感。datadirをまるっとコピーしてバグレポートできると吉。
どっちのシグナルにしろ起動したら上がっちゃったなら、ハードウェアの一過性の障害という可能性もある。 dmesg やハードウェアのログも見るのを忘れずに。あとは mysqlcheck --all-databases とかしておくといいかも知れない。
……っていうのを某氏向けに書いていたんだけどすっかり時期を逸したので、ここでおとむらい。

MySQL 8.0.17のCLONE INSTANCE FROMを使うとすごく楽にレプリケーションスレーブが作れる

TL;DR

  • 日々の覚書: MySQL 8.0.17でついにCloneプラグインが入った で紹介した CLONE LOCAL DATA は現在のdatadirをローカルのファイルシステムに一貫性のある形でコピーするステートメントだった
  • これをスレーブになるサーバーに転送してやってももちろん良いんだけど、そこまで一括でやってくれる CLONE INSTANCE FROM のステートメントも存在する
  • スレーブ増やすのが捗る

CLONE INSTANCE FROM を使うためには、データのコピー元( ドキュメント 上では ドナー(Donor) )とコピー先(同 レシピエント(Recipient) )それぞれのMySQLでCloneプラグインが有効化されていないといけない。
donor> INSTALL PLUGIN clone SONAME 'mysql_clone.so';
recipient> INSTALL PLUGIN clone SONAME 'mysql_clone.so';
ちなみにレシピエントでCloneプラグインが有効になってないとそもそもCLONEステートメントが転けるし、
recipient> CLONE INSTANCE FROM cloner@127.0.0.1:12345 IDENTIFIED BY '';
ERROR 1524 (HY000): Plugin 'clone' is not loaded
ドナーで有効になっていないと
recipient> CLONE INSTANCE FROM cloner@127.0.0.1:12345 IDENTIFIED BY '';
ERROR 3862 (HY000): Clone Donor Error: 1524 : Plugin 'clone' is not loaded.
とそれぞれ違うエラーが出る(レシピエントとしてのエラー3862と、ドナーが返したであろうエラーの1524が1つのメッセージに混じっていてちょっと面白い)
Cloneプラグインを両方で有効化したら、ドナーになるインスタンスでアカウントを作成する。必要になる権限は BACKUP_ADMIN のみ。ここは CLONE LOCAL DATA の時といっしょ。
donor> CREATE USER clone_user;
Query OK, 0 rows affected (0.01 sec)

donor> GRANT BACKUP_ADMIN ON *.* TO clone_user;
Query OK, 0 rows affected (0.00 sec)
レシピエント側で CLONE INSTANCE FROM を実行する。ユーザー名、ホスト名やIPアドレス、ポートの部分は クォートしない ( CHANGE MASTER TO はクォートしないといけないのに…)、パスワードを設定していなくても(そんなことがあるのか) IDENTIFIED BY .. はつけないと構文エラーになる、あたりが注意点。
ポート番号も、デフォルトの3306でも省略できずちゃんとフルで書かないとシンタックスエラーって言われる。
recipient> CLONE INSTANCE FROM clone_user@172.17.0.10:3306 IDENTIFIED BY '';
ERROR 3869 (HY000): Clone system configuration: 172.17.0.10:3306 is not found in clone_valid_donor_list:
おっとエラー。
CLONE INSTANCE FROM で指定する先は clone_valid_donor_list というパラメーターにセットしてやらないといけない。
recipient> SET GLOBAL clone_valid_donor_list = '172.17.0.10:3306';
Query OK, 0 rows affected (0.00 sec)

recipient> CLONE INSTANCE FROM clone_user@172.17.0.10:3306 IDENTIFIED BY '';
これでデータのコピーが始まる。
コピーが終わると勝手に RESTART ステートメントが走っておしまい。
RESTART の条件である「 mysqld_safesystemd にぶら下がっていること」が満たされてないとシャットダウンだけするっぽい)
再起動してきたら、 performance_schema.clone_status あたりからbinlogの情報とかgtid_executedとかが拾えるのでいつも通り CHANGE MASTER TO でレプリケーションを構成してやればスレーブが出来上がる。
レプリケーション用のアカウントとかはよしなに今までと同じ感じで作っておく。
donor> use performance_schema
Database changed

donor> show tables like '%clone%';
+----------------------------------------+
| Tables_in_performance_schema (%clone%) |
+----------------------------------------+
| clone_progress                         |
| clone_status                           |
+----------------------------------------+
2 rows in set (0.01 sec)

donor> SELECT * FROM clone_status;
+------+------+-----------+-------------------------+-------------------------+-----------------+----------------+----------+---------------+---------------+-----------------+-------------------------------------------------------------------------------------------+
| ID   | PID  | STATE     | BEGIN_TIME              | END_TIME                | SOURCE          | DESTINATION    | ERROR_NO | ERROR_MESSAGE | BINLOG_FILE   | BINLOG_POSITION | GTID_EXECUTED                                                                             |
+------+------+-----------+-------------------------+-------------------------+-----------------+----------------+----------+---------------+---------------+-----------------+-------------------------------------------------------------------------------------------+
|    1 |    0 | Completed | 2019-07-26 10:49:46.370 | 2019-07-26 11:01:59.458 | 172.17.0.10:3306 | LOCAL INSTANCE |        0 |               | binlog.000003 |             155 | 7470a831-4aed-11e9-b334-70106f4f8c56:1-8218993,
ee20abe3-33e8-11e9-8a63-1c98ec2973a4:1-16 |
+------+------+-----------+-------------------------+-------------------------+-----------------+----------------+----------+---------------+---------------+-----------------+-------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

donor> CHANGE MASTER TO master_host= '172.17.0.1', master_port= 3306, master_user = 'replicator', master_password= '', master_log_file= 'binlog.000003', master_log_pos= 155;
gtid_mode=ON ならもっと楽ですね! 捗る!!!

2019年7月24日水曜日

MySQL 8.0.17でついにCloneプラグインが入った

TL;DR


取り敢えず CLONE LOCAL DATA の方。
準備は INSTALL PLUGIN で一発。
mysql80 35> INSTALL PLUGIN CLONE SONAME "mysql_clone.so";
Query OK, 0 rows affected (0.01 sec)

mysql80 35> SHOW PLUGINS;
+---------------------------------+----------+--------------------+-----------------+---------+
| Name                            | Status   | Type               | Library         | License |
+---------------------------------+----------+--------------------+-----------------+---------+
..
| clone                           | ACTIVE   | CLONE              | mysql_clone.so  | GPL     |
+---------------------------------+----------+--------------------+-----------------+---------+
46 rows in set (0.00 sec)
使い方も簡単。 CLONE LOCAL DATA DIRECTORY /tmp/clone とかこれだけ。
ディレクトリーは書き込み権限があれば大丈夫。 CLONE LOCAL DATA ステートメントを実行するアカウントには BACKUP_ADMIN 権限が要るが、それ以外(たとえば、グローバルSELECTとかFLUSHとか)は要らない。
mysql80 35> create user yoku0825;
Query OK, 0 rows affected (0.01 sec)

mysql80 35> grant backup_admin on *.* TO yoku0825;
Query OK, 0 rows affected (0.00 sec)

mysql80 70> SHOW GRANTS;
+---------------------------------------------+
| Grants for yoku0825@%                       |
+---------------------------------------------+
| GRANT USAGE ON *.* TO `yoku0825`@`%`        |
| GRANT BACKUP_ADMIN ON *.* TO `yoku0825`@`%` |
+---------------------------------------------+
2 rows in set (0.00 sec)

mysql80 70> CLONE LOCAL DATA DIRECTORY '/tmp/clone';
Query OK, 0 rows affected (3.66 sec)
tpcc_start -u tpcc -w 10 -S /usr/mysql/8.0.17/data/mysql.sock -d tpcc -l 1200 -r 0 しながらローカルクローンしてみる。
mysql80 35> CLONE LOCAL DATA DIRECTORY '/tmp/clone';
Query OK, 0 rows affected (7.78 sec)

$ ll /tmp/clone
total 161804
drwxr-x--- 2 yoku0825 yoku0825       85 Jul 24 18:31 #clone
drwxr-x--- 2 yoku0825 yoku0825       19 Jul 24 18:31 d1
-rw-r----- 1 yoku0825 yoku0825 12582912 Jul 24 18:31 ibdata1
-rw-r----- 1 yoku0825 yoku0825 50331648 Jul 24 18:31 ib_logfile0
-rw-r----- 1 yoku0825 yoku0825 50331648 Jul 24 18:31 ib_logfile1
drwxr-x--- 2 yoku0825 yoku0825        6 Jul 24 18:31 mysql
-rw-r----- 1 yoku0825 yoku0825 24117248 Jul 24 18:31 mysql.ibd
drwxr-x--- 2 yoku0825 yoku0825       27 Jul 24 18:31 sys
drwxr-x--- 2 yoku0825 yoku0825     4096 Jul 24 18:31 tpcc
-rw-r----- 1 yoku0825 yoku0825 14680064 Jul 24 18:31 undo_001
-rw-r----- 1 yoku0825 yoku0825 13631488 Jul 24 18:31 undo_002

$ du -sh /tmp/clone
1.1G    /tmp/clone
その間のCommit per Secはこんな感じになった。
2019-07-24 18:30:33     value:0/1s      variable_name:Handler_commit
2019-07-24 18:30:34     value:3365/1s   variable_name:Handler_commit
2019-07-24 18:30:35     value:4616/1s   variable_name:Handler_commit
2019-07-24 18:30:36     value:5040/1s   variable_name:Handler_commit
2019-07-24 18:30:37     value:5043/1s   variable_name:Handler_commit
2019-07-24 18:30:38     value:4081/1s   variable_name:Handler_commit
2019-07-24 18:30:39     value:5448/1s   variable_name:Handler_commit
2019-07-24 18:30:40     value:4167/1s   variable_name:Handler_commit
2019-07-24 18:30:41     value:5259/1s   variable_name:Handler_commit
2019-07-24 18:30:42     value:4897/1s   variable_name:Handler_commit
2019-07-24 18:30:43     value:4807/1s   variable_name:Handler_commit
2019-07-24 18:30:44     value:5556/1s   variable_name:Handler_commit
2019-07-24 18:30:45     value:5892/1s   variable_name:Handler_commit
2019-07-24 18:30:46     value:5263/1s   variable_name:Handler_commit
2019-07-24 18:30:47     value:5093/1s   variable_name:Handler_commit
2019-07-24 18:30:48     value:5727/1s   variable_name:Handler_commit
2019-07-24 18:30:49     value:5506/1s   variable_name:Handler_commit
2019-07-24 18:30:50     value:5612/1s   variable_name:Handler_commit
2019-07-24 18:30:51     value:6066/1s   variable_name:Handler_commit
2019-07-24 18:30:52     value:4491/1s   variable_name:Handler_commit
2019-07-24 18:30:53     value:4460/1s   variable_name:Handler_commit
2019-07-24 18:30:54     value:4901/1s   variable_name:Handler_commit
2019-07-24 18:30:56     value:4807/1s   variable_name:Handler_commit
2019-07-24 18:30:57     value:5649/1s   variable_name:Handler_commit
2019-07-24 18:30:58     value:4307/1s   variable_name:Handler_commit
2019-07-24 18:30:59     value:4661/1s   variable_name:Handler_commit
2019-07-24 18:31:00     value:4864/1s   variable_name:Handler_commit
2019-07-24 18:31:01     value:5460/1s   variable_name:Handler_commit
2019-07-24 18:31:02     value:4245/1s   variable_name:Handler_commit
2019-07-24 18:31:03     value:4109/1s   variable_name:Handler_commit
2019-07-24 18:31:04     value:1661/1s   variable_name:Handler_commit <-- CLONE LOCAL DATA開始
2019-07-24 18:31:05     value:1950/1s   variable_name:Handler_commit
2019-07-24 18:31:06     value:2399/1s   variable_name:Handler_commit
2019-07-24 18:31:07     value:2168/1s   variable_name:Handler_commit
2019-07-24 18:31:08     value:2121/1s   variable_name:Handler_commit <-- CLONE LOCAL DATA終了
2019-07-24 18:31:09     value:4773/1s   variable_name:Handler_commit
2019-07-24 18:31:10     value:4563/1s   variable_name:Handler_commit
2019-07-24 18:31:11     value:4592/1s   variable_name:Handler_commit
2019-07-24 18:31:12     value:5245/1s   variable_name:Handler_commit
2019-07-24 18:31:13     value:4650/1s   variable_name:Handler_commit
2019-07-24 18:31:14     value:5380/1s   variable_name:Handler_commit
2019-07-24 18:31:15     value:4874/1s   variable_name:Handler_commit
2019-07-24 18:31:16     value:4629/1s   variable_name:Handler_commit
2019-07-24 18:31:17     value:4493/1s   variable_name:Handler_commit
優秀なのでは!?
エラーログはこんな感じに出てた。Noteなので log_error_verbosity= 3 が必要。
2019-07-24T18:31:03.279399+09:00 35 [Note] [MY-013457] [InnoDB] Clone Begin Master Task by root@localhost
2019-07-24T18:31:03.279482+09:00 35 [Note] [MY-013457] [InnoDB] Clone Apply Master Loop Back
2019-07-24T18:31:03.279494+09:00 35 [Note] [MY-013457] [InnoDB] Clone Apply Begin Master Task
2019-07-24T18:31:03.279727+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 1
2019-07-24T18:31:03.279749+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:03.279779+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 1
2019-07-24T18:31:03.279793+09:00 35 [Note] [MY-013458] [InnoDB] Clone State BEGIN FILE COPY
2019-07-24T18:31:03.295060+09:00 35 [Note] [MY-011845] [InnoDB] Clone Start PAGE ARCH : start LSN : 1354569844, checkpoint LSN : 13458
13923
2019-07-24T18:31:03.295198+09:00 35 [Note] [MY-013458] [InnoDB] Clone State FILE COPY : 25 chunks,  chunk size : 64 M
2019-07-24T18:31:03.295584+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 1
2019-07-24T18:31:03.295609+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State FILE COPY:
2019-07-24T18:31:03.295674+09:00 35 [Note] [MY-011978] [InnoDB] Clone estimated size: 1.00 GiB Available space: 3.06 GiB
2019-07-24T18:31:03.775468+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 20% completed.
2019-07-24T18:31:04.884874+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 40% completed.
2019-07-24T18:31:06.387871+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 60% completed.
2019-07-24T18:31:07.846118+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 80% completed.
2019-07-24T18:31:08.347343+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Tune Threads from: 1 to: 2 prev: 1 target: 2.'
2019-07-24T18:31:08.348284+09:00 0 [Note] [MY-013457] [InnoDB] Clone Begin Task ID: 1
2019-07-24T18:31:08.348325+09:00 0 [Note] [MY-013457] [InnoDB] Clone Apply Begin Task ID: 1
2019-07-24T18:31:08.521355+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Total Data: 928 MiB @ 177 MiB/sec, Network: 0 MiB @ 0 MiB/sec.'
2019-07-24T18:31:08.521409+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 2
2019-07-24T18:31:08.521428+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:08.521444+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 2
2019-07-24T18:31:08.521455+09:00 35 [Note] [MY-013458] [InnoDB] Clone State BEGIN PAGE COPY
2019-07-24T18:31:08.544317+09:00 35 [Note] [MY-011840] [InnoDB] Clone Start LOG ARCH : start LSN : 1347785138
2019-07-24T18:31:08.544373+09:00 35 [Note] [MY-011846] [InnoDB] Clone Stop  PAGE ARCH : end   LSN : 1347785138, log sys LSN : 1355428039
2019-07-24T18:31:08.544804+09:00 35 [Note] [MY-013458] [InnoDB] Clone State PAGE COPY : 1551 pages, 78 duplicate pages, 1 chunks,  chunk size : 64 M
2019-07-24T18:31:08.646061+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 2
2019-07-24T18:31:08.646130+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State PAGE COPY:
2019-07-24T18:31:10.222406+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 100% completed.
2019-07-24T18:31:10.222447+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Total Data: 952 MiB @ 137 MiB/sec, Network: 0 MiB @ 0 MiB/sec.'
2019-07-24T18:31:10.222461+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 3
2019-07-24T18:31:10.222470+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:10.222480+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 2
2019-07-24T18:31:10.222487+09:00 35 [Note] [MY-013458] [InnoDB] Clone State BEGIN REDO COPY
2019-07-24T18:31:10.340523+09:00 35 [Note] [MY-011841] [InnoDB] Clone Stop  LOG ARCH : end LSN : 1356084650
2019-07-24T18:31:10.340576+09:00 35 [Note] [MY-013458] [InnoDB] Clone State REDO COPY : 3 chunks,  chunk size : 64 M
2019-07-24T18:31:10.442258+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 2
2019-07-24T18:31:10.442296+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State REDO COPY:
2019-07-24T18:31:10.450725+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 33% completed.
2019-07-24T18:31:10.450778+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 66% completed.
2019-07-24T18:31:10.450791+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 100% completed.
2019-07-24T18:31:10.550946+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Total Data: 960 MiB @ 132 MiB/sec, Network: 0 MiB @ 0 MiB/sec.'
2019-07-24T18:31:10.550995+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 4
2019-07-24T18:31:10.551009+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:10.551019+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 2
2019-07-24T18:31:10.551026+09:00 35 [Note] [MY-013458] [InnoDB] Clone State DONE
2019-07-24T18:31:10.654535+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 2
2019-07-24T18:31:10.654584+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State FLUSH DATA:
2019-07-24T18:31:10.697683+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State FLUSH REDO:
2019-07-24T18:31:11.015694+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State DONE
2019-07-24T18:31:11.059224+09:00 0 [Note] [MY-013457] [InnoDB] Clone Apply End Task ID: 1 Passed, code: 0:
2019-07-24T18:31:11.059277+09:00 0 [Note] [MY-013457] [InnoDB] Clone End Task ID: 1 Passed, code: 0:
2019-07-24T18:31:11.059677+09:00 35 [Note] [MY-013457] [InnoDB] Clone Apply End Master Task ID: 0 Passed, code: 0:
2019-07-24T18:31:11.059910+09:00 35 [Note] [MY-013457] [InnoDB] Clone End Master Task ID: 0 Passed, code: 0:
取り敢えず感動をお伝えしたかった。

2019年6月3日月曜日

第一印象 of MySQL Ripple

TL;DR

  • MySQL Ripple を試してそっと閉じたメモ。
  • 多分 こういう状態で使うんだと思う
    • マスターの部分はよしなに冗長化されていると思いねえ
    • (おそらく準同期レプリケーションで)マスターに直接スレーブをぶら下げると死んじゃうようなケース
    • あと、このMySQL Ripple自体もたぶん多段構成するんだろうな、とデフォルトのパラメーター(主に -ripple-master-port )を見て思う

ビルド

Dockerイメージで起動

$ docker run -v $PWD:/root/binlog mysql-ripple \
  --ripple-server-address=0.0.0.0 \
  --ripple-master-address=172.17.0.3 \
  --ripple-master-port=3306 \
  --ripple-datadir=/root/binlog
ホスト側にbinlogの保管ディレクトリーをマウントしてるのは深い意味はない。
-ripple-server-address は外側のIPアドレスなり0.0.0.0なりにしておかないと他所のホストからつつけない(デフォルトがlocalhostなので)
-ripple-master-port のデフォルトが3306 ではなく MySQL Rippleが使う51005なので、MySQL Ripple同士で多段構成するのが前提なのかも知れない。

コマンドラインクライアントで接続してみる

  • デフォルトのポートは51005
  • 接続すること自体はできるが、クエリーのパースはできないので、何かコマンドやSQLを叩いても大抵エラーになる
$ mysql -h172.17.0.4 -P51005
Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 28
Server version: 5.6.0-ripple ripple version comment

mysql> status
ERROR 2013 (HY000): Lost connection to MySQL server during query

mysql> SHOW MASTER LOGS;
ERROR 2006 (HY000): MySQL server has gone away
No connection. Trying to reconnect...
Connection id:    28
Current database: *** NONE ***

ERROR 2013 (HY000): Lost connection to MySQL server during query

マスターにぶら下げてみる

  • gtid_mode= ON のみのサポート
  • master_log_file とか設定するオプションはないし、 gtid_mode != ON なところにぶら下げようとすると怒られる
I0603 09:05:54.490025     7 mysql_client_connection.cc:148] connected to host: 172.17.0.5, port: 3306
I0603 09:05:54.493810     7 mysql_master_session.cc:137] Connected to host: 172.17.0.5, port: 3306, server_id: 102, server_name:
W0603 09:05:54.495193     7 mysql_master_session.cc:197] master does not support semi sync
I0603 09:05:54.495231     7 mysql_master_session.cc:206] start replicating from 'f9874359-85da-11e9-a9fb-0242ac110003:0-0-4'
I0603 09:05:54.495659     7 mysql_master_session.cc:229] Master session entering main loop
E0603 09:05:54.495913     7 mysql_master_session.cc:296] Failed to read packet: Got error reading packet from server: The replication sender thread cannot start in AUTO_POSITION mode: this server has GTID_MODE = OFF instead of ON.
I0603 09:05:54.495939     7 binlog.cc:675] Connection closed last position binlog file: binlog.000000:1608, gtid: 0-0-4

スレーブをぶら下げてみる

  • こっちももちろん gtid_mode= ON のみのサポート
mysql> CHANGE MASTER TO master_host= '172.17.0.4', master_port= 51005, master_user= 'root' /* Non-GTID */;
Query OK, 0 rows affected, 2 warnings (0.04 sec)

mysql> start slave;
Query OK, 0 rows affected (0.01 sec)

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State:
                  Master_Host: 172.17.0.4
                  Master_User: root
                  Master_Port: 51005
..
                Last_IO_Errno: 1593
                Last_IO_Error: The replication receiver thread cannot start because the master has GTID_MODE = ON and this server has GTID_MODE = OFF.
               Last_SQL_Errno: 0
               Last_SQL_Error:
..
  • gtid_mode >= ON_PERMISSIVE にして master_auto_position= 1 で設定すると動く
    • ちゃんとデータも転送されてきた。
mysql> stop slave;
Query OK, 0 rows affected (0.01 sec)

mysql> CHANGE MASTER TO master_auto_position = 1;
Query OK, 0 rows affected (0.01 sec)

mysql> start slave;
Query OK, 0 rows affected (0.01 sec)

mysql> SHOW SLAVE STATUS\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 172.17.0.4
                  Master_User: root
                  Master_Port: 51005
..
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
..

MySQL Rippleの吐いたバイナリログファイル

  • よく訓練されたMySQLerにはわかると思うんだけど、フツーのバイナリログとちょっと違う。
    • ちなみにマスターはMySQL 5.7.26でbinlog_format= ROW
$ xxd binlog.000000
0000000: fe62 696e 0000 0000 0f53 b601 00f0 0000  .bin.....S......
0000010: 00f4 0000 0000 0004 0035 2e36 2e30 2d72  .........5.6.0-r
0000020: 6970 706c 6500 0000 0000 0000 0000 0000  ipple...........
..
00000f0: 0413 0400 0000 0000 0fea 0300 0073 0000  .............s..
0000100: 0067 0100 0000 0004 0035 2e37 2e32 362d  .g.......5.7.26-
0000110: 6c6f 6700 0000 0000 0000 0000 0000 0000  log.............
0000120: 0000 0000 0000 0000 0000 0000 0000 0000  ................
0000130: 0000 0000 0000 0000 0000 008a dcf4 5c13  ..............\.
0000140: 380d 0008 0012 0004 0404 0412 0000 5f00  8............._.
0000150: 041a 0800 0000 0808 0802 0000 000a 0a0a  ................
0000160: 2a2a 0012 3400 0000 0000 0096 53b6 0100  **..4.......S...
0000170: 2b00 0000 9201 0000 0000 ff00 0000 81dd  +...............
0000180: f45c 78c0 0e77 0815 e466 fa6c bd26 d9f5  .\x..w...f.l.&..
0000190: b607 3200 0000 b929 f7d4 aa18 4bdf 954e  ..2....)....K..N
  • マスターから取り出した生のバイナリログはこちら
$ xxd 935510b1506e-bin.000001
0000000: fe62 696e 8adc f45c 0fea 0300 0077 0000  .bin...\.....w..
0000010: 007b 0000 0001 0004 0035 2e37 2e32 362d  .{.......5.7.26-
0000020: 6c6f 6700 0000 0000 0000 0000 0000 0000  log.............
..
00000f0: 0000 0000 0000 0200 001f 0000 0000 0000  ................
0000100: 0120 00a0 5500 0000 0006 0373 7464 042d  . ..U......std.-
0000110: 002d 002d 000c 0164 3100 6431 0043 5245  .-.-...d1.d1.CRE
0000120: 4154 4520 4441 5441 4241 5345 2064 31e9  ATE DATABASE d1.
0000130: 5801 e9d4 dcf4 5c21 ea03 0000 4100 0000  X.....\!....A...
0000140: 7401 0000 0000 01f9 8743 5985 da11 e9a9  t........CY.....
0000150: fb02 42ac 1100 0302 0000 0000 0000 0002  ..B.............
0000160: 0100 0000 0000 0000 0200 0000 0000 0000  ................
0000170: 69f5 fb70 d4dc f45c 02ea 0300 0070 0000  i..p...\.....p..
0000180: 00e4 0100 0000 0004 0000 0000 0000 0002  ................
0000190: 0000 1f00 0000 0000 0001 2000 a055 0000  .......... ..U..
00001a0: 0000 0603 7374 6404 2d00 2d00 2d00 0c01  ....std.-.-.-...
00001b0: 6431 0064 3100 6372 6561 7465 2074 6162  d1.d1.create tab
00001c0: 6c65 2074 3120 286e 756d 2069 6e74 2c20  le t1 (num int,
00001d0: 7661 6c20 7661 7263 6861 7228 3332 2929  val varchar(32))
..
binlog_format= ROWでもフツーに記録されるはずのDDLが目視できない。 mysqlbinlog で食わせようとしても食えない。
どうやら暗号化されているっぽい。
$ docker run mysql-ripple --help | less
..
    -ripple_encryption_scheme (Encryption scheme used by ripple for local
      binlogs) type: int32 default: 255
..
-ripple-encryption-scheme=0 にすると暗号化されなくなって読めるようになる。
ただし rippled さん、結構バイナリログをバッファリングする(メモリー上にため込んで、 bin.000000 になかなか吐かない)ので、このあたりの動作を試して変だなと思ったらコンテナを止めてみるとフラッシュされたりする。
あと、 -ripple-encryption-scheme=255 で吐かせたバイナリログが残っているとそれに合わせて(?)同じ方式で暗号化し続けるっぽいので、 bin.000000 とかも削除して吸わせなおした方がいいと思われる。試すなら。
バイナリログを暗号化しておけるのは良いとして “MySQL Rippleからなら特に気にせず吸い上げられちゃう” ような気がするので、今のところあんまり期待してはいけないのかも知れない。難読化、くらいのつもりで。