MySQL5.6-rcでmysqlfailoverを試してみた

先日MySQL5.6のRC版がリリースされてMySQL WorkbenchにMHAみたいな事が出来るmysqlfailoverコマンドが追加されたので試してみました。
先に書いてしまうとそのままだとエラーとなり、正常に動作しないため、replication.pyとか変更することで動作しました。
最初の方には過程をダラダラと書いているため、要点だけ見たい方は最後の方まですっ飛ばして下さい。

検証した環境

  • KVM上のCentOS6.3 64bit
  • MySQL5.6はRC版を使用
  • MySQL Workbenchは5.2.44を使用
  • MySQL5.6は5670,5671,5672ポートで起動
  • Masterは5670、Slaveは5671,5672ポートを使用

ダウンロードとインストール

# wget http://dev.mysql.com/get/Downloads/MySQLGUITools/mysql-workbench-gpl-5.2.44-src.tar.gz/from/http://cdn.mysql.com/
# tar zxf mysql-workbench-gpl-5.2.44-src.tar.gz
# cd mysql-workbench-gpl-5.2.44-src/ext/mysql-utilities
# python setup.py install --prefix=/usr/local/mysql-wb

全部入れようとするとXとか必要なのでコマンドだけインストール。

prefix指定するとmysqlfailover実行時にライブラリ見つからないよと怒られるので適宜exportする。

# export PYTHONPATH=/usr/local/mysql-wb/lib/python2.6/site-packages

mysqlfailoverを使う場合は5.6から追加されたGlobal Transaction IDを使用する、またmaster.infoとかをテーブルに保存する必要があるのでmy.cnfに以下内容を設定する。

log-bin=mysql-bin
log-slave-updates
gtid-mode=ON
disable-gtid-unsafe-statements
master_info_repository=TABLE
relay_log_info_repository=TABLE
report_host=mysql-5.6-5670
report_port=5670

report_host, report_portはMaster, Slaveでそれぞれ別な物を設定する。
disable-gtid-unsafe-statementsを設定するとトランザクションが使えないテーブル(MyISAMとか)への更新が以下のようにエラーになるためInnoDBのみで使用する事になりそうです。

ERROR 1785 (HY000): Updates to non-transactional tables are forbidden when DISABLE_GTID_UNSAFE_STATEMENTS = 1.

ただ、GRANT文なんかは使えるのでInnoDBしか使わない前提であればそんなに気にならなそうです。

レプリケーション用アカウント(show grants forの結果)

GRANT REPLICATION SLAVE, REPLICATION CLIENT ON *.* TO 'repl'@'127.0.0.1' IDENTIFIED BY PASSWORD '*省略'

なんでこんなの書いたかというと、127.0.0.1のせいではまったから…

ということで実際に動かしてみる。オプションについては--help等でご確認下さい。

# /usr/local/mysql-wb/bin/mysqlfailover \
    --master=root@127.0.0.1:5670 \
    --slaves=root@127.0.0.1:5671,root@127.0.0.1:5672  \
    --candidates=root@127.0.0.1:5671 \
    --log=/tmp/failover.log

実行すると以下のような表示になります。感覚的にはtopコマンド近いかと。

MySQL Replication Failover Utility
Failover Mode = auto     Next Interval = Tue Oct 30 01:05:03 2012

Master Information
------------------
Binary Log File   Position  Binlog_Do_DB  Binlog_Ignore_DB  
mysql-bin.000005  455                                       

Replication Health Status
+------------+-------+---------+--------+------------+---------+
| host       | port  | role    | state  | gtid_mode  | health  |
+------------+-------+---------+--------+------------+---------+
| 127.0.0.1  | 5670  | MASTER  | UP     | ON         | OK      |
| 127.0.0.1  | 5671  | SLAVE   | UP     | ON         | OK      |
| 127.0.0.1  | 5672  | SLAVE   | UP     | ON         | OK      |
+------------+-------+---------+--------+------------+---------+

Q-quit R-refresh H-health G-GTID Lists U-UUIDs L-log entries

この状態でMasterを停止します。するとmysqlfailoverを実行していたコンソールが以下のように止まってしまい、フェールオーバーしません。

Failover starting in 'auto' mode...
# Candidate 127.0.0.1:5671 does not meet the requirements.
WARNING: None of the candidates was the best slave.
No candidate found for failover.
ERROR: No candidate found for failover.

以下は/tmp/failover.logへの出力
2012-10-30 01:20:28 AM INFO Master may be down. Waiting for 3 seconds.
2012-10-30 01:20:31 AM INFO Cannot reconnect to master.
2012-10-30 01:20:34 AM CRITICAL Master is confirmed to be down or unreachable.
2012-10-30 01:20:34 AM INFO Failover starting in 'auto' mode...
2012-10-30 01:20:34 AM WARNING Candidate 127.0.0.1:5671 does not meet the requirements.
2012-10-30 01:20:34 AM WARNING WARNING: None of the candidates was the best slave.
2012-10-30 01:20:34 AM CRITICAL No candidate found for failover.
2012-10-30 01:20:34 AM INFO Unregistering instance on master.
2012-10-30 01:20:34 AM CRITICAL No candidate found for failover.

この状態でMasterのMySQLを起動して再度実行すると以下のようなメッセージが表示されます。

Multiple instances of failover console found for master 127.0.0.1:5670.
If this is an error, restart the console with --force. 
Failover mode changed to 'FAIL' for this instance. 

そのため、気になる人は事前にmysql.failover_consoleテーブルをdeleteして空にしましょう。

mysql> use mysql
Database changed
mysql> select * from failover_console; 
+-----------+------+
| host      | port |
+-----------+------+
| 127.0.0.1 | 5670 |
+-----------+------+
1 row in set (0.00 sec)

mysql> delete from failover_console; 
Query OK, 1 row affected (0.01 sec)

mysql> select * from failover_console;
Empty set (0.00 sec)

mysql> 

もう少し詳細な情報が欲しいので-vオプションを追加します。

# /usr/local/mysql-wb/bin/mysqlfailover \
    --master=root@127.0.0.1:5670 \
    --slaves=root@127.0.0.1:5671,root@127.0.0.1:5672  \
    --candidates=root@127.0.0.1:5671 \
    --log=/tmp/failover.log \
    -v

先ほどの画面にも情報が増えますが省略します。再度Masterを停止する。以下その際の出力内容。

Failover starting in 'auto' mode...
# Checking eligibility of slave 127.0.0.1:5671 for candidate.
#   GTID_MODE=ON ... Ok
#   Replication user exists ... FAIL
# Candidate 127.0.0.1:5671 does not meet the requirements.
WARNING: None of the candidates was the best slave.
# Checking eligibility of slave 127.0.0.1:5671 for candidate.
#   GTID_MODE=ON ... Ok
#   Replication user exists ... FAIL
# Checking eligibility of slave 127.0.0.1:5672 for candidate.
#   GTID_MODE=ON ... Ok
#   Replication user exists ... FAIL
No candidate found for failover.
ERROR: No candidate found for failover.

以下同様にfailover.logへの出力。
2012-10-30 01:27:17 AM INFO Master may be down. Waiting for 3 seconds.
2012-10-30 01:27:20 AM INFO Cannot reconnect to master.
2012-10-30 01:27:23 AM CRITICAL Master is confirmed to be down or unreachable.
2012-10-30 01:27:23 AM INFO Failover starting in 'auto' mode...
2012-10-30 01:27:23 AM INFO Checking eligibility of slave 127.0.0.1:5671 for candidate.
2012-10-30 01:27:23 AM INFO GTID_MODE=ON ... Ok
2012-10-30 01:27:23 AM WARNING Replication user exists ... FAIL
2012-10-30 01:27:23 AM WARNING Candidate 127.0.0.1:5671 does not meet the requirements.
2012-10-30 01:27:23 AM WARNING WARNING: None of the candidates was the best slave.
2012-10-30 01:27:23 AM INFO Checking eligibility of slave 127.0.0.1:5671 for candidate.
2012-10-30 01:27:23 AM INFO GTID_MODE=ON ... Ok
2012-10-30 01:27:23 AM WARNING Replication user exists ... FAIL
2012-10-30 01:27:23 AM INFO Checking eligibility of slave 127.0.0.1:5672 for candidate.
2012-10-30 01:27:23 AM INFO GTID_MODE=ON ... Ok
2012-10-30 01:27:23 AM WARNING Replication user exists ... FAIL
2012-10-30 01:27:23 AM CRITICAL No candidate found for failover.
2012-10-30 01:27:23 AM INFO Unregistering instance on master.
2012-10-30 01:27:23 AM CRITICAL No candidate found for failover.

"Replication user exists ... FAIL"あたりから絞っていく。該当のソースはtopology.pyのこの辺り。

   660          # Check replication user - must exist with correct privileges
   661          user, passwd = slave.get_rpl_user()
   662          msg = "#   Replication user exists ... %s"
   663          if user is None or slave.check_rpl_user(user, slave.host) != []:
   664              if not self.force:
   665                  if self.verbose and not quiet:
   666                      self._report(msg % "FAIL", logging.WARN)
   667                  return (False, "RPL_USER",
   668                          "Candidate slave is missing replication user.")
   669              else:
   670                  self._report("Replication user not found but --force used.",
   671                               logging.WARN)
   672          elif self.verbose and not quiet:
   673              self._report(msg % "Ok")

パラメータ確認用のコードを追加しながら確認したところ、user, passwdに適切な値が入って来ていない。replication.pyの以下処理が悪そうなことが判明。

  1011      def _build_dictionary(self, rows):
  1012          """Build the internal dictionary of values.
  1013          
  1014          rows[in]       Rows as read from the file or table
  1015          """
  1016          for i in range(0, len(rows)):
  1017              self.values[_MASTER_INFO_COL[i]] = rows[i]

_MASTER_INFO_COLはソースコードの頭の方で以下のように定義されている。

    30  _MASTER_INFO_COL = [
    31      'Master_Log_File', 'Read_Master_Log_Pos', 'Master_Host', 'Master_User',
    32      'Master_Password', 'Master_Port', 'Connect_Retry', 'Master_SSL_Allowed',
    33      'Master_SSL_CA_File', 'Master_SSL_CA_Path', 'Master_SSL_Cert',
    34      'Master_SSL_Cipher', 'Master_SSL_Key', 'Master_SSL_Verify_Server_Cert',
    35      'Heartbeat', 'Bind', 'Ignored_server_ids', 'Uuid', 'Retry_count',
    36      'SSL_CRL', 'SSL_CRL_Path', 'Enabled_auto_position',
    37  ]

若干説明をはぶき気味ですが、iが0からスタートしてしまうとキーと値が1つずれてしまい、

  • Master_Userにパスワード
  • Master_PasswordにMasterのポート番号

が入ってしまいます。

ということで以下のように修正します。[2011/11/01 追記: 次の日記で修正箇所を変更しています]

# diff -urN mysql-wb/lib/python2.6/site-packages/mysql/utilities/common/replication.py{.20121030,}
--- mysql-wb/lib/python2.6/site-packages/mysql/utilities/common/replication.py.20121030	2012-09-27 05:50:38.000000000 +0900
+++ mysql-wb/lib/python2.6/site-packages/mysql/utilities/common/replication.py	2012-10-30 01:44:07.680981924 +0900
@@ -1014,7 +1014,7 @@
         rows[in]       Rows as read from the file or table
         """
         for i in range(0, len(rows)):
-            self.values[_MASTER_INFO_COL[i]] = rows[i]
+            self.values[_MASTER_INFO_COL[i+1]] = rows[i]
             
     
     def _read_master_info_file(self):
#

修正したら再度mysqlfailoverを実行する。ところがまたエラー… ぶっちゃけエラー内容も変化が無い。再び"WARNING Replication user exists ... FAIL"周辺を確認する。
どうやらslave.check_rpl_user(user, slave.host)の戻りがおかしい。ということでこれが定義されているserver.pyの処理を追いかける。537行目のuser_host_existsで失敗してるっぽい。以下該当箇所の抜粋。

   537      def user_host_exists(self, user, host_or_ip):
(略)
   550          res = self.exec_query("SELECT host FROM mysql.user WHERE user = '%s' AND '%s' LIKE host " % (user, host_or_ip))

ここで値を取った所、hostが127.0.0.1であって欲しいのにlocalhostになっていた。正直なんでやねん、とか思いながらも引き続きソースおっかける。すると805行目のcheck_rpl_userで置き換えられてた…

   805      def check_rpl_user(self, user, host):
(略)
   813          
   814          from mysql.utilities.common.user import User
   815          
   816          errors = []
   817          if host == '127.0.0.1':
   818              host = 'localhost'

先に書いた通りレプリケーションユーザはrepl@127.0.0.1で作成しているのでrepl@localhostな感じで存在確認されても存在しないことになる。ということで正しいかは分からないけどとりあえずこの処理をコメントアウト

# diff -urN mysql-wb/lib/python2.6/site-packages/mysql/utilities/common/server.py{.20121030,}
--- mysql-wb/lib/python2.6/site-packages/mysql/utilities/common/server.py.20121030	2012-09-27 05:50:47.000000000 +0900
+++ mysql-wb/lib/python2.6/site-packages/mysql/utilities/common/server.py	2012-10-30 02:05:54.921983906 +0900
@@ -814,8 +814,8 @@
         from mysql.utilities.common.user import User
         
         errors = []
-        if host == '127.0.0.1':
-            host = 'localhost'
+        #if host == '127.0.0.1':
+        #    host = 'localhost'
         result = self.user_host_exists(user, host)
         if result is None or result == []:
             errors.append("The replication user %s@%s was not found "
#

ということで今度こそとmysqlfailoverを再実行すると、ようやく上手く動作しました。コンソールの出力とログの出力。

Failover starting in 'auto' mode...
# Checking eligibility of slave 127.0.0.1:5671 for candidate.
#   GTID_MODE=ON ... Ok
#   Replication user exists ... Ok
# Candidate slave 127.0.0.1:5671 will become the new master.
# Preparing candidate for failover.
# LOCK STRING: FLUSH TABLES WITH READ LOCK
# Connecting candidate to 127.0.0.1:5672 as a master to retrieve unprocessed GTIDs.
# Change master command for 127.0.0.1:5671
# CHANGE MASTER TO MASTER_HOST = '127.0.0.1', MASTER_USER = 'repl', MASTER_PASSWORD = 'パスワード, MASTER_PORT = 5672, MASTER_AUTO_POSITION=1
# UNLOCK STRING: UNLOCK TABLES
# Waiting for candidate to catch up to slave 127.0.0.1:5672.
# Slave 127.0.0.1:5671:
# QUERY = SELECT SQL_THREAD_WAIT_AFTER_GTIDS('D7C09068-1DC7-11E2-BFB8-00163E6535F2:1-36', 3)
# Return Code = 0
# Creating replication user if it does not exist.
# Stopping slaves.
# Performing STOP on all slaves.
#   Executing stop on slave 127.0.0.1:5671 Ok
#   Executing stop on slave 127.0.0.1:5672 Ok
# Switching slaves to new master.
# Change master command for 127.0.0.1:5671
# CHANGE MASTER TO MASTER_HOST = '127.0.0.1', MASTER_USER = 'repl', MASTER_PASSWORD = 'パスワード', MASTER_PORT = 5671, MASTER_AUTO_POSITION=1
# Change master command for 127.0.0.1:5672
# CHANGE MASTER TO MASTER_HOST = '127.0.0.1', MASTER_USER = 'repl', MASTER_PASSWORD = 'パスワード', MASTER_PORT = 5671, MASTER_AUTO_POSITION=1
# Starting slaves.
# Performing START on all slaves.
#   Executing start on slave 127.0.0.1:5672 Ok
# Checking slaves for errors.
# 127.0.0.1:5672 status: Ok 
# Failover complete.

Failover console will restart in 5 seconds.

以下/tmp/failover.log
2012-10-30 02:12:34 AM INFO Master may be down. Waiting for 3 seconds.
2012-10-30 02:12:37 AM INFO Cannot reconnect to master.
2012-10-30 02:12:40 AM CRITICAL Master is confirmed to be down or unreachable.
2012-10-30 02:12:40 AM INFO Failover starting in 'auto' mode...
2012-10-30 02:12:40 AM INFO Checking eligibility of slave 127.0.0.1:5671 for candidate.
2012-10-30 02:12:40 AM INFO GTID_MODE=ON ... Ok
2012-10-30 02:12:40 AM INFO Replication user exists ... Ok
2012-10-30 02:12:40 AM INFO Candidate slave 127.0.0.1:5671 will become the new master.
2012-10-30 02:12:40 AM INFO Preparing candidate for failover.
2012-10-30 02:12:40 AM INFO Connecting candidate to 127.0.0.1:5672 as a master to retrieve unprocessed GTIDs.
2012-10-30 02:13:31 AM INFO Waiting for candidate to catch up to slave 127.0.0.1:5672.
2012-10-30 02:13:31 AM INFO Creating replication user if it does not exist.
2012-10-30 02:13:31 AM INFO Stopping slaves.
2012-10-30 02:13:31 AM INFO Performing STOP on all slaves.
2012-10-30 02:13:31 AM INFO Executing stop on slave 127.0.0.1:5671 Ok
2012-10-30 02:13:31 AM INFO Executing stop on slave 127.0.0.1:5672 Ok
2012-10-30 02:13:31 AM INFO Switching slaves to new master.
2012-10-30 02:13:31 AM INFO Starting slaves.
2012-10-30 02:13:31 AM INFO Performing START on all slaves.
2012-10-30 02:14:22 AM INFO Executing start on slave 127.0.0.1:5672 Ok
2012-10-30 02:14:22 AM INFO Checking slaves for errors.
2012-10-30 02:14:22 AM INFO 127.0.0.1:5672 status: Ok
2012-10-30 02:14:22 AM INFO Failover complete.

5秒待つとまたtopのような画面になりますが、Master, Slaveが変わっている事がわかります。なお参照するMasterが変更となったSlaveのSQL_THREADは停止した状態となるようです。[2011/11/05追記]START SLAVEしてるのにエラーとなるようなのでどこかおかしいっぽいです。

| host       | port  | role    | state  | gtid_mode  | health                      | version       | master_log_file   | master_log_pos  | IO_Thread  | SQL_Thread  | Secs_Behind  | Remaining_Delay  | IO_Error_Num  | IO_Error  | SQL_Error_Num  | SQL_Error                                   | Trans_Behind  |
+------------+-------+---------+--------+------------+-----------------------------+---------------+-------------------+-----------------+------------+-------------+--------------+------------------+---------------+-----------+----------------+---------------------------------------------+---------------+
| 127.0.0.1  | 5671  | MASTER  | UP     | ON         | OK                          | 5.6.7-rc-log  | mysql-bin.000003  | 7319            |            |             |              |                  |               |           |                |                                             |               |
| 127.0.0.1  | 5672  | SLAVE   | UP     | ON         | SQL thread is not running.  | 5.6.7-rc-log  | mysql-bin.000003  | 191             | Yes        | No          | 0            | No               | 0             |           | 1593           | Failed during slave workers initialization  | 0             |
+------------+-------+---------+--------+------------+-----------------------------+---------------+-------------------+-----------------+------------+-------------+--------------+------------------+---------------+-----------+----------------+---------------------------------------------+---------------+

ということで想定通り動作するようになりました。今回は同一のサーバ上で3つのMySQLを起動している環境のため、実運用に近い環境(全部別な物理サーバでMySQLが稼働)ではreplication.pyを修正するだけで動作するのではないかと。後日全部別環境にして動作するか試してみたいと思います。
※初めて書いた日記なので色々適当になっているのでそのうち修正するかもしれません…