MHA自動(dòng)Failover與自已手工Failover的切換原理
發(fā)表時(shí)間：2023-08-28 來源：明輝站整理相關(guān)軟件相關(guān)文章人氣：
[摘要]集群信息角色 IP地址 ServerID 類型Master 192.168.244.10 1 寫入Candicate...
集群信息角色 IP地址 ServerID 類型
Master 192.168.244.10 1 寫入
Candicate master 192.168.244.20 2 讀
Slave 192.168.244.30 3 讀
Monitor host 192.168.244.40 監(jiān)控集群組
MHA具體的搭建步驟和原理，可參考另外一篇博客：
MySQL高可用方案MHA的部署和原理
自動(dòng)Failover
為了通過MHA的日志清晰判斷MHA自動(dòng)Failover的實(shí)現(xiàn)原理，需模擬如下場景：
當(dāng)主庫發(fā)生故障時(shí)，master中還有一部分binlog日志沒有傳輸?shù)紺andicate master和Slave上，且Slave上的二進(jìn)制日志多于Candicate master上。
嘗試了幾種方案，總算如愿以償。
方案一：
1. 關(guān)閉Candicate master和Slave的主從復(fù)制。
2. 通過存儲過程生成測試數(shù)據(jù)
3. 開啟Candicate master和Slave的主從復(fù)制并kill掉master的mysqld進(jìn)程，模擬主庫發(fā)生故障，進(jìn)行自動(dòng)failover操作
為此，還特意寫了個(gè)腳本，可惜的是，效果并不理想，在自動(dòng)Failover的過程中，顯示MHA Manager到master的“SSH is NOT reachable”。
方案二：
通過tc命令對Candicate master和Slave的網(wǎng)卡分別設(shè)置不同的傳輸速率，確保發(fā)送到Candicate master的日志量小于Slave上的。
很可惜，效果同方案一一樣。
方案三：
在主從復(fù)制中，直接關(guān)閉master的mysqld數(shù)據(jù)庫。
但是，通過這樣方式，并不會實(shí)現(xiàn)Slave上的二進(jìn)制日志多于Candicate master的效果。
方案四：
通過截取relay log，在關(guān)掉slave的情況下，修改master.info和relay-log.info的位置點(diǎn)來人為制造Candicate master的日志量小于Slave的。
事后想想，其實(shí)這樣的方法就等同于先關(guān)閉Candicate master的主從復(fù)制，再在master上執(zhí)行一段操作，再關(guān)閉slave上的主從復(fù)制，再在master上執(zhí)行一段操作。
這樣不就實(shí)現(xiàn)了master的binlog > slave 的relay log > Candicate master的relay log。
方案四總算如愿以償
下面通過方案四看看MHA的實(shí)現(xiàn)原理
1. 創(chuàng)建測試表，并插入測試數(shù)據(jù)
mysql> create table sbtest.b(id int,name varchar(10));
Query OK, 0 rows affected (0.12 sec)
mysql> insert into sbtest.b values(1,'a');
Query OK, 1 row affected (0.00 sec)
mysql> insert into sbtest.b values(2,'b');
Query OK, 1 row affected (0.01 sec)
mysql> insert into sbtest.b values(3,'c');
Query OK, 1 row affected (0.00 sec)
mysql> insert into sbtest.b values(4,'d');
Query OK, 1 row affected (0.00 sec)
mysql> insert into sbtest.b values(5,'e');
Query OK, 1 row affected (0.01 sec)
2. 分別查看master上binlog的內(nèi)容，slave上relay log的內(nèi)容
Master
mysql> show binlog events;+------------------+------+-------------+-----------+-------------+------------------------------------------------+ Log_name Pos Event_type Server_id End_log_pos Info +------------------+------+-------------+-----------+-------------+------------------------------------------------+ mysql-bin.000001 4 Format_desc 1 120 Server ver: 5.6.31-log, Binlog ver: 4 mysql-bin.000001 120 Query 1 238 create table sbtest.b(id int,name varchar(10)) mysql-bin.000001 238 Query 1 315 BEGIN mysql-bin.000001 315 Query 1 421 insert into sbtest.b values(1,'a') mysql-bin.000001 421 Xid 1 452 COMMIT /* xid=102 */ mysql-bin.000001 452 Query 1 529 BEGIN mysql-bin.000001 529 Query 1 635 insert into sbtest.b values(2,'b') mysql-bin.000001 635 Xid 1 666 COMMIT /* xid=103 */ mysql-bin.000001 666 Query 1 743 BEGIN mysql-bin.000001 743 Query 1 849 insert into sbtest.b values(3,'c') mysql-bin.000001 849 Xid 1 880 COMMIT /* xid=104 */ mysql-bin.000001 880 Query 1 957 BEGIN mysql-bin.000001 957 Query 1 1063 insert into sbtest.b values(4,'d') mysql-bin.000001 1063 Xid 1 1094 COMMIT /* xid=105 */ mysql-bin.000001 1094 Query 1 1171 BEGIN mysql-bin.000001 1171 Query 1 1277 insert into sbtest.b values(5,'e') mysql-bin.000001 1277 Xid 1 1308 COMMIT /* xid=106 */ +------------------+------+-------------+-----------+-------------+------------------------------------------------+17 rows in set (0.01 sec)
Slave
mysql> show relaylog events in 'mysqld-relay-bin.000002';+-------------------------+------+-------------+-----------+-------------+------------------------------------------------+ Log_name Pos Event_type Server_id End_log_pos Info +-------------------------+------+-------------+-----------+-------------+------------------------------------------------+ mysqld-relay-bin.000002 4 Format_desc 2 120 Server ver: 5.6.31-log, Binlog ver: 4 mysqld-relay-bin.000002 120 Rotate 1 0 mysql-bin.000001;pos=120 mysqld-relay-bin.000002 167 Format_desc 1 0 Server ver: 5.6.31-log, Binlog ver: 4 mysqld-relay-bin.000002 283 Query 1 238 create table sbtest.b(id int,name varchar(10)) mysqld-relay-bin.000002 401 Query 1 315 BEGIN mysqld-relay-bin.000002 478 Query 1 421 insert into sbtest.b values(1,'a') mysqld-relay-bin.000002 584 Xid 1 452 COMMIT /* xid=102 */ mysqld-relay-bin.000002 615 Query 1 529 BEGIN mysqld-relay-bin.000002 692 Query 1 635 insert into sbtest.b values(2,'b') mysqld-relay-bin.000002 798 Xid 1 666 COMMIT /* xid=103 */ mysqld-relay-bin.000002 829 Query 1 743 BEGIN mysqld-relay-bin.000002 906 Query 1 849 insert into sbtest.b values(3,'c') mysqld-relay-bin.000002 1012 Xid 1 880 COMMIT /* xid=104 */ mysqld-relay-bin.000002 1043 Query 1 957 BEGIN mysqld-relay-bin.000002 1120 Query 1 1063 insert into sbtest.b values(4,'d') mysqld-relay-bin.000002 1226 Xid 1 1094 COMMIT /* xid=105 */ mysqld-relay-bin.000002 1257 Query 1 1171 BEGIN mysqld-relay-bin.000002 1334 Query 1 1277 insert into sbtest.b values(5,'e') mysqld-relay-bin.000002 1440 Xid 1 1308 COMMIT /* xid=106 */ +-------------------------+------+-------------+-----------+-------------+------------------------------------------------+19 rows in set (0.00 sec)
通過對比master中的binlog event，可以看到show relaylog events中的End_log_pos實(shí)際上指的是對應(yīng)的二進(jìn)制事件在binlog的位置。
再來查看Candicate master中對應(yīng)的relay log的內(nèi)容
[root@node2 mysql]# mysqlbinlog mysqld-relay-bin.000002
[root@node2 mysql]# mysqlbinlog mysqld-relay-bin.000002/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=1*/;/*!40019 SET @@session.max_insert_delayed_threads=0*/;/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 4#170524 17:16:37 server id 2 end_log_pos 120 CRC32 0x4faba9ae Start: binlog v 4, server v 5.6.31-log created 170524 17:16:37BINLOG 'dU8lWQ8CAAAAdAAAAHgAAABAAAQANS42LjMxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAa6p
q08='/*!*/;# at 120#700101 8:00:00 server id 1 end_log_pos 0 CRC32 0x74c6d70c Rotate to mysql-bin.000001 pos: 120# at 167#170524 17:15:49 server id 1 end_log_pos 0 CRC32 0xed2672eb Start: binlog v 4, server v 5.6.31-log created 170524 17:15:49BINLOG 'RU8lWQ8BAAAAdAAAAAAAAAAAAAQANS42LjMxLWxvZwAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAAXAAEGggAAAAICAgCAAAACgoKGRkAAety
Ju0='/*!*/;# at 283#170524 17:17:20 server id 1 end_log_pos 238 CRC32 0xdd48c118 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617440/*!*/;
SET @@session.pseudo_thread_id=2/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/*!*/;
SET @@session.sql_mode=1075838976/*!*/;
SET @@session.auto_increment_increment=1, @@session.auto_increment_offset=1/*!*/;/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
SET @@session.lc_time_names=0/*!*/;
SET @@session.collation_database=DEFAULT/*!*/;
create table sbtest.b(id int,name varchar(10))/*!*/;
# at 401#170524 17:17:27 server id 1 end_log_pos 315 CRC32 0xae393750 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617447/*!*/;
BEGIN/*!*/;
# at 478#170524 17:17:27 server id 1 end_log_pos 421 CRC32 0x28a781ae Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617447/*!*/;
insert into sbtest.b values(1,'a')/*!*/;
# at 584#170524 17:17:27 server id 1 end_log_pos 452 CRC32 0x680f1bfe Xid = 29COMMIT/*!*/;
# at 615#170524 17:17:33 server id 1 end_log_pos 529 CRC32 0x6a1aae7e Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617453/*!*/;
BEGIN/*!*/;
# at 692#170524 17:17:33 server id 1 end_log_pos 635 CRC32 0x117786ca Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617453/*!*/;
insert into sbtest.b values(2,'b')/*!*/;
# at 798#170524 17:17:33 server id 1 end_log_pos 666 CRC32 0xa8400ec6 Xid = 30COMMIT/*!*/;
# at 829#170524 17:17:38 server id 1 end_log_pos 743 CRC32 0x24f9a1d2 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617458/*!*/;
BEGIN/*!*/;
# at 906#170524 17:17:38 server id 1 end_log_pos 849 CRC32 0x56fa9e89 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617458/*!*/;
insert into sbtest.b values(3,'c')/*!*/;
# at 1012#170524 17:17:38 server id 1 end_log_pos 880 CRC32 0x2ac656d4 Xid = 31COMMIT/*!*/;
# at 1043#170524 17:17:44 server id 1 end_log_pos 957 CRC32 0x73a903bf Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617464/*!*/;
BEGIN/*!*/;
# at 1120#170524 17:17:44 server id 1 end_log_pos 1063 CRC32 0x171b9b27 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617464/*!*/;
insert into sbtest.b values(4,'d')/*!*/;
# at 1226#170524 17:17:44 server id 1 end_log_pos 1094 CRC32 0x47d6fe57 Xid = 32COMMIT/*!*/;
# at 1257#170524 17:17:49 server id 1 end_log_pos 1171 CRC32 0x2d37da37 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617469/*!*/;
BEGIN/*!*/;
# at 1334#170524 17:17:49 server id 1 end_log_pos 1277 CRC32 0xd2201fa2 Query thread_id=2 exec_time=0 error_code=0SET TIMESTAMP=1495617469/*!*/;
insert into sbtest.b values(5,'e')/*!*/;
# at 1440#170524 17:17:49 server id 1 end_log_pos 1308 CRC32 0xac1b464e Xid = 33COMMIT/*!*/;
DELIMITER ;
# End of log fileROLLBACK /* added by mysqlbinlog */;/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;
View Code
mysql中binlog有個(gè)有意思的地方是，位置點(diǎn)其實(shí)是也是字節(jié)的大小。
譬如，上面這個(gè)relay log中，最后一個(gè)位點(diǎn)是# at 1440，算上最后一個(gè)commit操作需占用31個(gè)字節(jié)，所以整個(gè)文件的大小是1471，與實(shí)際大小吻合。
[root@node2 mysql]# ll mysqld-relay-bin.000002-rw-rw---- 1 mysql mysql 1471 May 24 17:17 mysqld-relay-bin.000002
3. 通過show slave status查看io thread和sql thread的位置信息
mysql> show slave status\G*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.168.244.10
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysql-bin.000001
Read_Master_Log_Pos: 1308
Relay_Log_File: mysqld-relay-bin.000002
Relay_Log_Pos: 1471
Relay_Master_Log_File: mysql-bin.000001
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 1308
Relay_Log_Space: 1645
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 0Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 1
Master_UUID: 2a6365e0-1d05-11e7-956d-000c29c64704
Master_Info_File: /var/lib/mysql/master.info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it
Master_Retry_Count: 86400
Master_Bind:
Last_IO_Error_Timestamp:
Last_SQL_Error_Timestamp:
Master_SSL_Crl:
Master_SSL_Crlpath:
Retrieved_Gtid_Set:
Executed_Gtid_Set:
Auto_Position: 01 row in set (0.00 sec)
待會兒需要修改上面Master_Log_File,Read_Master_Log_Pos,Relay_Log_File,Relay_Log_Pos,Relay_Master_Log_File,Exec_Master_Log_Pos的值。
雖然這幾個(gè)參數(shù)的值與master.info和relay-log.info文件是相對應(yīng)的，
但通過修改master.info和relay-log.info的值，并重啟slave，并不會將上述幾個(gè)參數(shù)值修改。
上述幾個(gè)參數(shù)是保存到內(nèi)存中的，唯一可行的方案是首先關(guān)閉slave實(shí)例，再修改master.info和relay-log.info文件，然后重新啟動(dòng)mysql實(shí)例。
4. 關(guān)閉Candicate master實(shí)例，剪裁relay log，修改master.info和relay-log.info文件。
關(guān)閉實(shí)例
[root@node2 mysql]# service mysqld stop
剪裁relay log
這里，寫了個(gè)python腳本實(shí)現(xiàn)該功能
#!/usr/bin/pythonf1 = open('mysqld-relay-bin.000002','r')
f2 = open('tmp_relay_bin','w+')
size1=f1.read(615)f2.write(size1)
f1.seek(1471)
size2=f1.read()
f2.write(size2)
f1.close()
f2.close()
在上述腳本size1中，615對應(yīng)的是insert into sbtest.b values(1,'a')這條記錄
[root@node2 mysql]# python 1.py
[root@node2 mysql]# mv tmp_relay_bin mysqld-relay-bin.000002
修改master.info的內(nèi)容
主要是修改第三行
23mysql-bin.0000011308
修改為
23mysql-bin.000001452
修改relay-log.info的內(nèi)容
原文件如下：
7./mysqld-relay-bin.0000021471mysql-bin.0000011308001
修改為：
7./mysqld-relay-bin.000002615mysql-bin.000001452001
啟動(dòng)slave，注意，配置文件中必須設(shè)置skip-slave-start，不然它自動(dòng)開啟主從復(fù)制。
[root@node2 mysql]# service mysqld start
5. 對于slave，同樣如此處理，只不過relay log的位置點(diǎn)要靠后些
#!/usr/bin/pythonf1 = open('mysqld-relay-bin.000002','r')
f2 = open('tmp_relay_bin','w+')
size1=f1.read(1043)
f2.write(size1)
f1.seek(1471)
size2=f1.read()
f2.write(size2)
f1.close()
f2.close()
1043對應(yīng)的是insert into sbtest.b values(3,'c')這條記錄
修改master.info的內(nèi)容
23mysql-bin.000001
880
修改relay-log.info的內(nèi)容
7./mysqld-relay-bin.000002
1043mysql-bin.000001
8800
01
6. 開啟MHA監(jiān)控
# nohup masterha_manager --conf=/etc/masterha/app1.cnf --remove_dead_master_conf --ignore_last_failover < /dev/null >
/masterha/app1/manager.log 2>&1 &
# masterha_check_status --conf=/etc/masterha/app1.cnf
app1 (pid:1615) is running(0:PING_OK), master:192.168.244.10
7. 關(guān)閉master實(shí)例
# service mysqld stop
8. 查看MHA切換日志，了解整個(gè)切換過程。
該日志的時(shí)間點(diǎn)與上面relay log的時(shí)間點(diǎn)并不吻合，原因在于這個(gè)反復(fù)測試了很多次。
Sun May 21 20:50:46 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 20:50:46 2017 - [warning] Connection failed 1 time(s)..
Sun May 21 20:50:46 2017 - [info] Executing secondary network check script: /usr/local/bin/masterha_secondary_check -s 192.168.244.20 -s 192.168.244.30 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --master_user=monitor --master_password=monitor123 --ping_type=SELECT
Sun May 21 20:50:46 2017 - [info] Executing SSH check script: save_binary_logs --command=test --start_pos=4 --binlog_dir=/var/lib/mysql --output_file=/tmp/save_binary_logs_test --manager_version=0.56 --binlog_prefix=mysql-bin
Monitoring server 192.168.244.20 is reachable, Master is not reachable from 192.168.244.20. OK.
Sun May 21 20:50:46 2017 - [info] HealthCheck: SSH to 192.168.244.10 is reachable.
Monitoring server 192.168.244.30 is reachable, Master is not reachable from 192.168.244.30. OK.-- 當(dāng)monitor檢測到master mysqld不可用的時(shí)候，即根據(jù)masterha_secondary_check腳本從Candicate master和Slave上判斷master mysqld的可用性，
根據(jù)上面的顯示信息，通過192.168.244.20和192.168.244.30也判斷到master mysqld不可用。
如果任意一個(gè)slave判斷到master mysqld可用，則輸出的信息如下：
# /usr/local/bin/masterha_secondary_check -s 192.168.244.20 -s 192.168.244.30 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306
Master is reachable from 192.168.244.20!
Sun May 21 20:50:46 2017 - [info] Master is not reachable from all other monitoring servers. Failover should start.
Sun May 21 20:50:47 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 20:50:47 2017 - [warning] Connection failed 2 time(s)..
Sun May 21 20:50:48 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 20:50:48 2017 - [warning] Connection failed 3 time(s)..
Sun May 21 20:50:49 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 20:50:49 2017 - [warning] Connection failed 4 time(s)..
Sun May 21 20:50:49 2017 - [warning] Master is not reachable from health checker!Sun May 21 20:50:49 2017 - [warning] Master 192.168.244.10(192.168.244.10:3306) is not reachable!Sun May 21 20:50:49 2017 - [warning] SSH is reachable.-- 一共判斷了4次，均判斷master mysqld不可用，但是master主機(jī)通過ssh還是能登錄上去。
如果這里顯示的是SSH is NOT reachable，則代表master主機(jī)也已經(jīng)宕機(jī)了，
剛開始還以為是通過ssh來判斷主機(jī)是否宕機(jī)，但在之前的測試方案中（具體可見文末），master并沒有宕機(jī)，這里卻顯示SSH is NOT reachable.
通過上面的輸出才知道是通過save_binary_logs腳本來判斷ssh可用性的。
Sun May 21 20:50:49 2017 - [info] Connecting to a master server failed. Reading configuration file /etc/masterha_default.cnf and /etc/masterha/app1.cnf again, and trying to connect to all servers to check server status..
Sun May 21 20:50:49 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Sun May 21 20:50:49 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Sun May 21 20:50:49 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Sun May 21 20:50:50 2017 - [warning] SQL Thread is stopped(no error) on 192.168.244.20(192.168.244.20:3306)
Sun May 21 20:50:50 2017 - [warning] SQL Thread is stopped(no error) on 192.168.244.30(192.168.244.30:3306)
Sun May 21 20:50:50 2017 - [info] GTID failover mode = 0Sun May 21 20:50:50 2017 - [info] Dead Servers:
Sun May 21 20:50:50 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:50 2017 - [info] Alive Servers:
Sun May 21 20:50:50 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Sun May 21 20:50:50 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Sun May 21 20:50:50 2017 - [info] Alive Slaves:
Sun May 21 20:50:50 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 20:50:50 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:50 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 20:50:50 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 20:50:50 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:50 2017 - [info] Checking slave configurations..
Sun May 21 20:50:50 2017 - [info] Checking replication filtering settings..
Sun May 21 20:50:50 2017 - [info] Replication filtering check ok.
Sun May 21 20:50:50 2017 - [info] Master is down!Sun May 21 20:50:50 2017 - [info] Terminating monitoring script.
Sun May 21 20:50:50 2017 - [info] Got exit code 20 (Master dead).
Sun May 21 20:50:50 2017 - [info] MHA::MasterFailover version 0.56.
Sun May 21 20:50:50 2017 - [info] Starting master failover.-- 讀取MHA的配置文件，檢查slave的相關(guān)配置，比如read_only參數(shù)，是否設(shè)置了復(fù)制的過濾規(guī)則
從上面的輸出中可以看出，SQL Thread正常停止了并不影響MHA的切換。
Sun May 21 20:50:50 2017 - [info]
Sun May 21 20:50:50 2017 - [info] * Phase 1: Configuration Check Phase..
Sun May 21 20:50:50 2017 - [info]
Sun May 21 20:50:51 2017 - [warning] SQL Thread is stopped(no error) on 192.168.244.20(192.168.244.20:3306)
Sun May 21 20:50:51 2017 - [warning] SQL Thread is stopped(no error) on 192.168.244.30(192.168.244.30:3306)
Sun May 21 20:50:51 2017 - [info] GTID failover mode = 0Sun May 21 20:50:51 2017 - [info] Dead Servers:
Sun May 21 20:50:51 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:51 2017 - [info] Checking master reachability via MySQL(double check)...
Sun May 21 20:50:51 2017 - [info] ok.
Sun May 21 20:50:51 2017 - [info] Alive Servers:
Sun May 21 20:50:51 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Sun May 21 20:50:51 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Sun May 21 20:50:51 2017 - [info] Alive Slaves:
Sun May 21 20:50:51 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 20:50:51 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:51 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 20:50:51 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 20:50:51 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:51 2017 - [info] Starting SQL thread on 192.168.244.20(192.168.244.20:3306) ..
Sun May 21 20:50:51 2017 - [info] done.
Sun May 21 20:50:51 2017 - [info] Starting SQL thread on 192.168.244.30(192.168.244.30:3306) ..
Sun May 21 20:50:51 2017 - [info] done.
Sun May 21 20:50:51 2017 - [info] Starting Non-GTID based failover.
Sun May 21 20:50:51 2017 - [info]
Sun May 21 20:50:51 2017 - [info] ** Phase 1: Configuration Check Phase completed.-- 第一階段，檢查了MHA的配置信息，并再次判斷了master的可用性。
第二階段，關(guān)閉dead master。
包括執(zhí)行摘除master上的vip，同時(shí)執(zhí)行shutdown_script腳本，因?yàn)樵撃_本在配置文件中沒有定義，故跳過。
Sun May 21 20:50:51 2017 - [info]
Sun May 21 20:50:51 2017 - [info] * Phase 2: Dead Master Shutdown Phase..
Sun May 21 20:50:51 2017 - [info]
Sun May 21 20:50:51 2017 - [info] Forcing shutdown so that applications never connect to the current master..
Sun May 21 20:50:51 2017 - [info] Executing master IP deactivation script:
Sun May 21 20:50:51 2017 - [info] /usr/local/bin/master_ip_failover --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --command=stopssh --ssh_user=root
Disabling the VIP an old master: 192.168.244.10 SIOCSIFFLAGS: Cannot assign requested address
Sun May 21 20:50:51 2017 - [info] done.
Sun May 21 20:50:51 2017 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Sun May 21 20:50:51 2017 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Sun May 21 20:50:51 2017 - [info]
-- 第三階段 3.1 判斷哪個(gè)slave的二進(jìn)制日志是最新的。
通過下面的輸出可以看出，所有的slave中，最新的二進(jìn)制日志位置是mysql-bin.000001:880（通過show slave status中的Master_Log_File, Read_Master_Log_Pos得到）
最舊的二進(jìn)制日志位置是mysql-bin.000001:452
Sun May 21 20:50:51 2017 - [info] * Phase 3: Master Recovery Phase..
Sun May 21 20:50:51 2017 - [info]
Sun May 21 20:50:51 2017 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Sun May 21 20:50:51 2017 - [info]
Sun May 21 20:50:51 2017 - [info] The latest binary log file/position on all slaves is mysql-bin.000001:880Sun May 21 20:50:51 2017 - [info] Latest slaves (Slaves that received relay log files to the latest):
Sun May 21 20:50:51 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 20:50:51 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:51 2017 - [info] The oldest binary log file/position on all slaves is mysql-bin.000001:452Sun May 21 20:50:51 2017 - [info] Oldest slaves:
Sun May 21 20:50:51 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 20:50:51 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:51 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 20:50:51 2017 - [info]
-- 3.2 保存master的binlog
注意，上面已經(jīng)判斷到slave中最新二進(jìn)制日志是mysql-bin.000001:880，所以它把該位置后所有二進(jìn)制日志都拼接起來，并scp到monitor的/masterha/app1目錄下。
Sun May 21 20:50:51 2017 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..Sun May 21 20:50:51 2017 - [info]
Sun May 21 20:50:52 2017 - [info] Fetching dead master's binary logs..Sun May 21 20:50:52 2017 - [info] Executing command on the dead master 192.168.244.10(192.168.244.10:3306): save_binary_logs --command=save --start_file=mysql-bin.000001 --start_pos=880 --binlog_dir=/var/lib/mysql --output_file=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56
Creating /tmp if not exists.. ok.
Concat binary/relay logs from mysql-bin.000001 pos 880 to mysql-bin.000001 EOF into /tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog ..
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 120.. ok.
Dumping effective binlog data from /var/lib/mysql/mysql-bin.000001 position 880 to tail(1308).. ok.
Binlog Checksum enabled
Concat succeeded.
Sun May 21 20:50:52 2017 - [info] scp from root@192.168.244.10:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog to local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog succeeded.
Sun May 21 20:50:52 2017 - [info] HealthCheck: SSH to 192.168.244.20 is reachable.
Sun May 21 20:50:53 2017 - [info] HealthCheck: SSH to 192.168.244.30 is reachable.
Sun May 21 20:50:53 2017 - [info]
-- 3.3 選新主階段
首先判斷最新的slave中是否包括最舊的二進(jìn)制日志（mysql-bin.000001:452）以后的relay log。
接著選新主，
因?yàn)?92.168.244.20中設(shè)置了candidate_master設(shè)置了，所以192.168.244.20被指定為新主。
Sun May 21 20:50:53 2017 - [info] * Phase 3.3: Determining New Master Phase..
Sun May 21 20:50:53 2017 - [info]
Sun May 21 20:50:53 2017 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Sun May 21 20:50:53 2017 - [info] Checking whether 192.168.244.30 has relay logs from the oldest position..
Sun May 21 20:50:53 2017 - [info] Executing command: apply_diff_relay_logs --command=find --latest_mlf=mysql-bin.000001 --latest_rmlp=880 --target_mlf=mysql-bin.000001 --target_rmlp=452 --server_id=3 --workdir=/tmp --timestamp=20170521205050 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/ :
Opening /var/lib/mysql/relay-log.info ... ok.
Relay log found at /var/lib/mysql, up to mysqld-relay-bin.000003
Fast relay log position search failed. Reading relay logs to find..
Reading mysqld-relay-bin.000003
Binlog Checksum enabled
Reading mysqld-relay-bin.000002
Binlog Checksum enabled
Master Version is 5.6.31-log
Binlog Checksum enabled
mysqld-relay-bin.000002 contains master mysql-bin.000001 from position 120Target relay log FOUND!Sun May 21 20:50:53 2017 - [info] OK. 192.168.244.30 has all relay logs.
Sun May 21 20:50:53 2017 - [info] Searching new master from slaves..
Sun May 21 20:50:53 2017 - [info] Candidate masters from the configuration file:
Sun May 21 20:50:53 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 20:50:53 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 20:50:53 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 20:50:53 2017 - [info] Non-candidate masters:
Sun May 21 20:50:53 2017 - [info] Searching from candidate_master slaves which have received the latest relay log events..
Sun May 21 20:50:53 2017 - [info] Not found.
Sun May 21 20:50:53 2017 - [info] Searching from all candidate_master slaves..
Sun May 21 20:50:53 2017 - [info] New master is 192.168.244.20(192.168.244.20:3306)
Sun May 21 20:50:53 2017 - [info] Starting master failover..
Sun May 21 20:50:53 2017 - [info]
From:192.168.244.10(192.168.244.10:3306) (current master) +--192.168.244.20(192.168.244.20:3306) +--192.168.244.30(192.168.244.30:3306)
To:192.168.244.20(192.168.244.20:3306) (new master) +--192.168.244.30(192.168.244.30:3306)
Sun May 21 20:50:53 2017 - [info]
-- 3.3 獲取新主所需的差異二進(jìn)制日志，包括兩部分 1> 新主和最新的slave之間差異的relay log 2> 保存在MHA Manager上的最新的slave和原master之前差異的binlog
其中，差異的relay log通過如下方式獲�。�
ssh到192.168.244.30上，執(zhí)行apply_diff_relay_logs獲取差異的relay log。將差異的relay log scp到192.168.244.20。
Sun May 21 20:50:53 2017 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Sun May 21 20:50:53 2017 - [info]
Sun May 21 20:50:53 2017 - [info] Server 192.168.244.20 received relay logs up to: mysql-bin.000001:452Sun May 21 20:50:53 2017 - [info] Need to get diffs from the latest slave(192.168.244.30) up to: mysql-bin.000001:880 (using the latest slave's relay logs)Sun May 21 20:50:53 2017 - [info] Connecting to the latest slave host 192.168.244.30, generating diff relay log files..
Sun May 21 20:50:53 2017 - [info] Executing command: apply_diff_relay_logs --command=generate_and_send --scp_user=root --scp_host=192.168.244.20 --latest_mlf=mysql-bin.000001 --latest_rmlp=880 --target_mlf=mysql-bin.000001 --target_rmlp=452 --server_id=3 --diff_file_readtolatest=/tmp/relay_from_read_to_latest_192.168.244.20_3306_20170521205050.binlog --workdir=/tmp --timestamp=20170521205050 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/ Sun May 21 20:50:54 2017 - [info]
Opening /var/lib/mysql/relay-log.info ... ok.
Relay log found at /var/lib/mysql, up to mysqld-relay-bin.000003
Fast relay log position search failed. Reading relay logs to find..
Reading mysqld-relay-bin.000003
Binlog Checksum enabled
Reading mysqld-relay-bin.000002
Binlog Checksum enabled
Master Version is 5.6.31-log
Binlog Checksum enabled
mysqld-relay-bin.000002 contains master mysql-bin.000001 from position 120
Target relay log file/position found. start_file:mysqld-relay-bin.000002, start_pos:615.
Concat binary/relay logs from mysqld-relay-bin.000002 pos 615 to mysqld-relay-bin.000003 EOF into /tmp/relay_from_read_to_latest_192.168.244.20_3306_20170521205050.binlog ..
Binlog Checksum enabled
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 283.. ok.
Dumping effective binlog data from /var/lib/mysql/mysqld-relay-bin.000002 position 615 to tail(1066).. ok.
Dumping binlog head events (rotate events), skipping format description events from /var/lib/mysql/mysqld-relay-bin.000003.. Binlog Checksum enabled
dumped up to pos 120. ok.
No need to dump effective binlog data from /var/lib/mysql/mysqld-relay-bin.000003 (pos starts 120, filesize 120). Skipping.
Binlog Checksum enabled
Binlog Checksum enabled
Concat succeeded.
Generating diff relay log succeeded. Saved at /tmp/relay_from_read_to_latest_192.168.244.20_3306_20170521205050.binlog . scp node3:/tmp/relay_from_read_to_latest_192.168.244.20_3306_20170521205050.binlog to root@192.168.244.20(22) succeeded.
Sun May 21 20:50:54 2017 - [info] Generating diff files succeeded.
Sun May 21 20:50:54 2017 - [info] Sending binlog..
Sun May 21 20:50:54 2017 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog to root@192.168.244.20:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog succeeded.
Sun May 21 20:50:54 2017 - [info]
-- 3.4 應(yīng)用從master保存的二進(jìn)制日志事件
首先，等原來的所有的relay log都應(yīng)用完。
其次，再通過apply_diff_relay_logs應(yīng)用差異的relay log，及差異的binlog。
應(yīng)用完畢后，得到新的master binlog的文件和位置，其它slave可根據(jù)該文件和位置來建立主從復(fù)制關(guān)系。
第三，執(zhí)行master_ip_failover腳本，執(zhí)行如下操作 1> 將新主的read_only設(shè)置為0 2> 啟動(dòng)vip
Sun May 21 20:50:54 2017 - [info] * Phase 3.4: Master Log Apply Phase..
Sun May 21 20:50:54 2017 - [info]
Sun May 21 20:50:54 2017 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Sun May 21 20:50:54 2017 - [info] Starting recovery on 192.168.244.20(192.168.244.20:3306)..
Sun May 21 20:50:54 2017 - [info] Generating diffs succeeded.
Sun May 21 20:50:54 2017 - [info] Waiting until all relay logs are applied.
Sun May 21 20:50:54 2017 - [info] done.
Sun May 21 20:50:54 2017 - [info] Getting slave status..
Sun May 21 20:50:54 2017 - [info] This slave(192.168.244.20)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000001:452). No need to recover from Exec_Master_Log_Pos.Sun May 21 20:50:54 2017 - [info] Connecting to the target slave host 192.168.244.20, running recover script..
Sun May 21 20:50:54 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.168.244.20 --slave_ip=192.168.244.20 --slave_port=3306 --apply_files=/tmp/relay_from_read_to_latest_192.168.244.20_3306_20170521205050.binlog,/tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170521205050 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx
Sun May 21 20:50:55 2017 - [info]
Concat all apply files to /tmp/total_binlog_for_192.168.244.20_3306.20170521205050.binlog ..
Copying the first binlog file /tmp/relay_from_read_to_latest_192.168.244.20_3306_20170521205050.binlog to /tmp/total_binlog_for_192.168.244.20_3306.20170521205050.binlog.. ok.
Dumping binlog head events (rotate events), skipping format description events from /tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog.. Binlog Checksum enabled
dumped up to pos 120. ok. /tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog has effective binlog events from pos 120.
Dumping effective binlog data from /tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog position 120 to tail(548).. ok.
Concat succeeded.
All apply target binary logs are concatinated at /tmp/total_binlog_for_192.168.244.20_3306.20170521205050.binlog .
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/relay_from_read_to_latest_192.168.244.20_3306_20170521205050.binlog,/tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog on 192.168.244.20:3306. This may take long time...
Applying log files succeeded.
Sun May 21 20:50:55 2017 - [info] All relay logs were successfully applied.
Sun May 21 20:50:55 2017 - [info] Getting new master's binlog name and position..Sun May 21 20:50:55 2017 - [info] mysql-bin.000002:976Sun May 21 20:50:55 2017 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.244.20', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000002', MASTER_LOG_POS=976, MASTER_USER='repl', MASTER_PASSWORD='xxx';
Sun May 21 20:50:55 2017 - [info] Executing master IP activate script:
Sun May 21 20:50:55 2017 - [info] /usr/local/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --new_master_host=192.168.244.20 --new_master_ip=192.168.244.20 --new_master_port=3306 --new_master_user='monitor' --new_master_password='monitor123' Set read_only=0 on the new master.
Enabling the VIP 192.168.244.188 on the new master: 192.168.244.20 Sun May 21 20:50:55 2017 - [info] OK.
Sun May 21 20:50:55 2017 - [info] ** Finished master recovery successfully.
Sun May 21 20:50:55 2017 - [info] * Phase 3: Master Recovery Phase completed.-- 第四階段 slave恢復(fù)階段-- 4.1 因?yàn)?92.168.244.30擁有最新的relay log，所以也沒必要獲取差異的relay log-- 4.2 開始slave的恢復(fù)階段 1> 將monitor上保存的master上的差異的二進(jìn)制日志scp到slave上。 2> 應(yīng)用差異日志。 3> 清除原來的復(fù)制關(guān)系，并再次執(zhí)行change master命令建立新的主從同步。
如果有多個(gè)slave，則該恢復(fù)過程是并行的。
Sun May 21 20:50:55 2017 - [info]
Sun May 21 20:50:55 2017 - [info] * Phase 4: Slaves Recovery Phase..
Sun May 21 20:50:55 2017 - [info]
Sun May 21 20:50:55 2017 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Sun May 21 20:50:55 2017 - [info]
Sun May 21 20:50:55 2017 - [info] -- Slave diff file generation on host 192.168.244.30(192.168.244.30:3306) started, pid: 4966. Check tmp log /masterha/app1/192.168.244.30_3306_20170521205050.log if it takes time..
Sun May 21 20:50:56 2017 - [info]
Sun May 21 20:50:56 2017 - [info] Log messages from 192.168.244.30 ...
Sun May 21 20:50:56 2017 - [info]
Sun May 21 20:50:55 2017 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Sun May 21 20:50:56 2017 - [info] End of log messages from 192.168.244.30.
Sun May 21 20:50:56 2017 - [info] -- 192.168.244.30(192.168.244.30:3306) has the latest relay log events.
Sun May 21 20:50:56 2017 - [info] Generating relay diff files from the latest slave succeeded.
Sun May 21 20:50:56 2017 - [info]
Sun May 21 20:50:56 2017 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Sun May 21 20:50:56 2017 - [info]
Sun May 21 20:50:56 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) started, pid: 4968. Check tmp log /masterha/app1/192.168.244.30_3306_20170521205050.log if it takes time..
Sun May 21 20:50:58 2017 - [info]
Sun May 21 20:50:58 2017 - [info] Log messages from 192.168.244.30 ...
Sun May 21 20:50:58 2017 - [info]
Sun May 21 20:50:56 2017 - [info] Sending binlog..
Sun May 21 20:50:57 2017 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog to root@192.168.244.30:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog succeeded.
Sun May 21 20:50:57 2017 - [info] Starting recovery on 192.168.244.30(192.168.244.30:3306)..
Sun May 21 20:50:57 2017 - [info] Generating diffs succeeded.
Sun May 21 20:50:57 2017 - [info] Waiting until all relay logs are applied.
Sun May 21 20:50:57 2017 - [info] done.
Sun May 21 20:50:57 2017 - [info] Getting slave status..
Sun May 21 20:50:57 2017 - [info] This slave(192.168.244.30)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000001:880). No need to recover from Exec_Master_Log_Pos.Sun May 21 20:50:57 2017 - [info] Connecting to the target slave host 192.168.244.30, running recover script..
Sun May 21 20:50:57 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.168.244.30 --slave_ip=192.168.244.30 --slave_port=3306 --apply_files=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170521205050 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx
Sun May 21 20:50:57 2017 - [info]
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/saved_master_binlog_from_192.168.244.10_3306_20170521205050.binlog on 192.168.244.30:3306. This may take long time...
Applying log files succeeded.
Sun May 21 20:50:57 2017 - [info] All relay logs were successfully applied.
Sun May 21 20:50:57 2017 - [info] Resetting slave 192.168.244.30(192.168.244.30:3306) and starting replication from the new master 192.168.244.20(192.168.244.20:3306)..
Sun May 21 20:50:58 2017 - [info] Executed CHANGE MASTER.
Sun May 21 20:50:58 2017 - [info] Slave started.
Sun May 21 20:50:58 2017 - [info] End of log messages from 192.168.244.30.
Sun May 21 20:50:58 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) succeeded.
Sun May 21 20:50:58 2017 - [info] All new slave servers recovered successfully.-- 第五階段 清理階段
從MHA的配置文件中剔除server1的配置信息
Sun May 21 20:50:58 2017 - [info]
Sun May 21 20:50:58 2017 - [info] * Phase 5: New master cleanup phase..
Sun May 21 20:50:58 2017 - [info]
Sun May 21 20:50:58 2017 - [info] Resetting slave info on the new master..
Sun May 21 20:50:58 2017 - [info] 192.168.244.20: Resetting slave info succeeded.
Sun May 21 20:50:58 2017 - [info] Master failover to 192.168.244.20(192.168.244.20:3306) completed successfully.
Sun May 21 20:50:58 2017 - [info] Deleted server1 entry from /etc/masterha/app1.cnf .
Sun May 21 20:50:58 2017 - [info]
-- 生成 Failover 報(bào)告，發(fā)送告警郵件----- Failover Report -----app1: MySQL Master failover 192.168.244.10(192.168.244.10:3306) to 192.168.244.20(192.168.244.20:3306) succeeded
Master 192.168.244.10(192.168.244.10:3306) is down!Check MHA Manager logs at node4:/masterha/app1/manager.log for details.
Started automated(non-interactive) failover.
Invalidated master IP address on 192.168.244.10(192.168.244.10:3306)
The latest slave 192.168.244.30(192.168.244.30:3306) has all relay logs for recovery.
Selected 192.168.244.20(192.168.244.20:3306) as a new master.192.168.244.20(192.168.244.20:3306): OK: Applying all logs succeeded.192.168.244.20(192.168.244.20:3306): OK: Activated master IP address.192.168.244.30(192.168.244.30:3306): This host has the latest relay log events.
Generating relay diff files from the latest slave succeeded.192.168.244.30(192.168.244.30:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.244.20(192.168.244.20:3306)192.168.244.20(192.168.244.20:3306): Resetting slave info succeeded.
Master failover to 192.168.244.20(192.168.244.20:3306) completed successfully.
Sun May 21 20:50:58 2017 - [info] Sending mail..
Unknown option: conf
從上面的日志輸出可以看出整個(gè)MHA的切換過程
首先，MHA Manager檢測到master不可用，則會通過另外兩個(gè)slave檢查master的可用性。一共檢測4次。
同時(shí)判斷MHA Manager到master的ssh可用性。
ssh可用性的判斷結(jié)果影響后后續(xù)切換中的“Phase 3.2: Saving Dead Master's Binlog Phase”
Phase 1: Configuration Check Phase..
檢查了MHA的配置信息，并再次判斷了master的可用性。
Phase 2: Dead Master Shutdown Phase..
宕機(jī)的master處理階段，包括摘除VIP，執(zhí)行shutdown_script中定義的腳本。
Phase 3: Master Recovery Phase..
Phase 3.1: Getting Latest Slaves Phase..
判斷哪個(gè)slave擁有最新的relay log（通過比較show slave status中的Master_Log_File, Read_Master_Log_Pos位置），
哪個(gè)slave擁有最舊的relay log
Phase 3.2: Saving Dead Master's Binlog Phase..
根據(jù)上面得到的slave的最新位置信息，將差異的二進(jìn)制日志保存到MHA Manager的指定目錄下。
如果在第一步驟中，判斷了MHA Manager到master的ssh不可用，則會跳過這個(gè)階段。
Phase 3.3: Determining New Master Phase..
選擇新的master
Phase 3.3: New Master Diff Log Generation Phase..
將差異的relay log和master差異日志scp到新的master上。
Phase 3.4: Master Log Apply Phase..
首先，等待slave上已有的relay log都應(yīng)用完。
其次，通過apply_diff_relay_logs應(yīng)用差異的relay log，及差異的binlog。
應(yīng)用完畢后，得到新的master binlog的文件和位置，其它slave可根據(jù)該文件和位置來建立主從復(fù)制關(guān)系。
第三，執(zhí)行master_ip_failover腳本，執(zhí)行如下操作
1> 將新主的read_only設(shè)置為0
2> 啟動(dòng)vip
Phase 4: Slaves Recovery Phase
Phase 4.1: Starting Parallel Slave Diff Log Generation Phase
為slave獲取差異的relay log
因?yàn)?92.168.244.30擁有最新的relay log，所以也沒必要獲取差異的relay log
Phase 4.2: Starting Parallel Slave Log Apply Phase
開始slave的恢復(fù)階段
1> 將差異的relay log和master差異日志scp到slave上。
2> 應(yīng)用差異日志。
3> 清除原來的復(fù)制關(guān)系，并再次執(zhí)行change master命令建立新的主從同步。
如果有多個(gè)slave，則該恢復(fù)過程是并行的。
Phase 5: New master cleanup phase
從MHA的配置文件中剔除server1的配置信息
最后，生成Failover Report并發(fā)送告警郵件。
手動(dòng)Failover
與自動(dòng)Failover相對應(yīng)的是手動(dòng)Failover，即當(dāng)master發(fā)生故障時(shí)，通過手動(dòng)執(zhí)行腳本來進(jìn)行故障切換。
命令如下：
# masterha_master_switch --master_state=dead --conf=/etc/masterha/app1.cnf --dead_master_host=192.168.244.10 --dead_master_port=3306 --new_master_host=192.168.244.30 --new_master_port=3306 --ignore_last_failover
輸出日志信息如下：
--dead_master_ip=<dead_master_ip> is not set. Using 192.168.244.10.
Wed May 24 19:44:20 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed May 24 19:44:20 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Wed May 24 19:44:20 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Wed May 24 19:44:20 2017 - [info] MHA::MasterFailover version 0.56.
Wed May 24 19:44:20 2017 - [info] Starting master failover.
Wed May 24 19:44:20 2017 - [info]
Wed May 24 19:44:20 2017 - [info] * Phase 1: Configuration Check Phase..
Wed May 24 19:44:20 2017 - [info]
Wed May 24 19:44:21 2017 - [info] GTID failover mode = 0Wed May 24 19:44:21 2017 - [info] Dead Servers:
Wed May 24 19:44:21 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:21 2017 - [info] Checking master reachability via MySQL(double check)...
Wed May 24 19:44:21 2017 - [info] ok.
Wed May 24 19:44:21 2017 - [info] Alive Servers:
Wed May 24 19:44:21 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Wed May 24 19:44:21 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:44:21 2017 - [info] Alive Slaves:
Wed May 24 19:44:21 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:44:21 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:21 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:44:21 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:44:21 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Master 192.168.244.10(192.168.244.10:3306) is dead. Proceed? (yes/NO): yes
Wed May 24 19:44:23 2017 - [info] Starting Non-GTID based failover.
Wed May 24 19:44:23 2017 - [info]
Wed May 24 19:44:23 2017 - [info] ** Phase 1: Configuration Check Phase completed.
Wed May 24 19:44:23 2017 - [info]
Wed May 24 19:44:23 2017 - [info] * Phase 2: Dead Master Shutdown Phase..
Wed May 24 19:44:23 2017 - [info]
Wed May 24 19:44:24 2017 - [info] HealthCheck: SSH to 192.168.244.10 is reachable.
Wed May 24 19:44:24 2017 - [info] Forcing shutdown so that applications never connect to the current master..
Wed May 24 19:44:24 2017 - [info] Executing master IP deactivation script:
Wed May 24 19:44:24 2017 - [info] /usr/local/bin/master_ip_failover --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --command=stopssh --ssh_user=root Disabling the VIP an old master: 192.168.244.10 SIOCSIFFLAGS: Cannot assign requested address
Wed May 24 19:44:24 2017 - [info] done.
Wed May 24 19:44:24 2017 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Wed May 24 19:44:24 2017 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] * Phase 3: Master Recovery Phase..
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] The latest binary log file/position on all slaves is mysql-bin.000002:120Wed May 24 19:44:24 2017 - [info] Latest slaves (Slaves that received relay log files to the latest):
Wed May 24 19:44:24 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:44:24 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info] The oldest binary log file/position on all slaves is mysql-bin.000002:120Wed May 24 19:44:24 2017 - [info] Oldest slaves:
Wed May 24 19:44:24 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:44:24 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:44:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..Wed May 24 19:44:24 2017 - [info]
Wed May 24 19:44:24 2017 - [info] Fetching dead master's binary logs..Wed May 24 19:44:24 2017 - [info] Executing command on the dead master 192.168.244.10(192.168.244.10:3306): save_binary_logs --comman
d=save --start_file=mysql-bin.000002 --start_pos=120 --binlog_dir=/var/lib/mysql --output_file=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 Creating /tmp if not exists.. ok.
Concat binary/relay logs from mysql-bin.000002 pos 120 to mysql-bin.000002 EOF into /tmp/saved_master_binlog_from_192.168.244.10_330
6_20170524194420.binlog .. Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 120.. ok.
Dumping effective binlog data from /var/lib/mysql/mysql-bin.000002 position 120 to tail(143).. ok.
Binlog Checksum enabled
Concat succeeded.
saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog 100% 143 0.1KB/s 00:00 Wed May 24 19:44:24 2017 - [info] scp from root@192.168.244.10:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlo
g to local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog succeeded.Wed May 24 19:44:25 2017 - [info] HealthCheck: SSH to 192.168.244.20 is reachable.
Wed May 24 19:44:25 2017 - [info] HealthCheck: SSH to 192.168.244.30 is reachable.
Wed May 24 19:44:25 2017 - [info]
Wed May 24 19:44:25 2017 - [info] * Phase 3.3: Determining New Master Phase..
Wed May 24 19:44:25 2017 - [info]
Wed May 24 19:44:25 2017 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Wed May 24 19:44:25 2017 - [info] All slaves received relay logs to the same position. No need to resync each other.
Wed May 24 19:44:25 2017 - [info] 192.168.244.30 can be new master.
Wed May 24 19:44:25 2017 - [info] New master is 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:44:25 2017 - [info] Starting master failover..
Wed May 24 19:44:25 2017 - [info]
From:192.168.244.10(192.168.244.10:3306) (current master) +--192.168.244.20(192.168.244.20:3306) +--192.168.244.30(192.168.244.30:3306)
To:192.168.244.30(192.168.244.30:3306) (new master) +--192.168.244.20(192.168.244.20:3306)
Starting master switch from 192.168.244.10(192.168.244.10:3306) to 192.168.244.30(192.168.244.30:3306)? (yes/NO): yes
Wed May 24 19:44:32 2017 - [info] New master decided manually is 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:44:32 2017 - [info]
Wed May 24 19:44:32 2017 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Wed May 24 19:44:32 2017 - [info]
Wed May 24 19:44:32 2017 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Wed May 24 19:44:32 2017 - [info] Sending binlog..
saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog 100% 143 0.1KB/s 00:00 Wed May 24 19:44:33 2017 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog to
root@192.168.244.30:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog succeeded.Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] * Phase 3.4: Master Log Apply Phase..
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Wed May 24 19:44:33 2017 - [info] Starting recovery on 192.168.244.30(192.168.244.30:3306)..
Wed May 24 19:44:33 2017 - [info] Generating diffs succeeded.
Wed May 24 19:44:33 2017 - [info] Waiting until all relay logs are applied.
Wed May 24 19:44:33 2017 - [info] done.
Wed May 24 19:44:33 2017 - [info] Getting slave status..
Wed May 24 19:44:33 2017 - [info] This slave(192.168.244.30)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000002:120). No need to recover from Exec_Master_Log_Pos.Wed May 24 19:44:33 2017 - [info] Connecting to the target slave host 192.168.244.30, running recover script..
Wed May 24 19:44:33 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.168.244.30 --slave_ip=192.168.244.30 --slave_port=3306 --apply_files=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170524194420 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxxWed May 24 19:44:33 2017 - [info]
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog on 192.168.244.30:3306. This may take long time...Applying log files succeeded.
Wed May 24 19:44:33 2017 - [info] All relay logs were successfully applied.
Wed May 24 19:44:33 2017 - [info] Getting new master's binlog name and position..Wed May 24 19:44:33 2017 - [info] mysql-bin.000001:1429Wed May 24 19:44:33 2017 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_
HOST='192.168.244.30', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000001', MASTER_LOG_POS=1429, MASTER_USER='repl', MASTER_PASSWORD='xxx';Wed May 24 19:44:33 2017 - [info] Executing master IP activate script:
Wed May 24 19:44:33 2017 - [info] /usr/local/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --new_master_host=192.168.244.30 --new_master_ip=192.168.244.30 --new_master_port=3306 --new_master_user='monitor' --new_master_password='monitor123' Set read_only=0 on the new master.
Enabling the VIP 192.168.244.188 on the new master: 192.168.244.30 Wed May 24 19:44:33 2017 - [info] OK.
Wed May 24 19:44:33 2017 - [info] ** Finished master recovery successfully.
Wed May 24 19:44:33 2017 - [info] * Phase 3: Master Recovery Phase completed.
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] * Phase 4: Slaves Recovery Phase..
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Wed May 24 19:44:33 2017 - [info]
Wed May 24 19:44:33 2017 - [info] -- Slave diff file generation on host 192.168.244.20(192.168.244.20:3306) started, pid: 1598. Check
tmp log /masterha/app1/192.168.244.20_3306_20170524194420.log if it takes time..Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:34 2017 - [info] Log messages from 192.168.244.20 ...
Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:33 2017 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Wed May 24 19:44:34 2017 - [info] End of log messages from 192.168.244.20.
Wed May 24 19:44:34 2017 - [info] -- 192.168.244.20(192.168.244.20:3306) has the latest relay log events.
Wed May 24 19:44:34 2017 - [info] Generating relay diff files from the latest slave succeeded.
Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:34 2017 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Wed May 24 19:44:34 2017 - [info]
Wed May 24 19:44:34 2017 - [info] -- Slave recovery on host 192.168.244.20(192.168.244.20:3306) started, pid: 1600. Check tmp log /ma
sterha/app1/192.168.244.20_3306_20170524194420.log if it takes time..saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog 100% 143 0.1KB/s 00:00 Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:35 2017 - [info] Log messages from 192.168.244.20 ...
Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:34 2017 - [info] Sending binlog..
Wed May 24 19:44:35 2017 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog to
root@192.168.244.20:/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog succeeded.Wed May 24 19:44:35 2017 - [info] Starting recovery on 192.168.244.20(192.168.244.20:3306)..
Wed May 24 19:44:35 2017 - [info] Generating diffs succeeded.
Wed May 24 19:44:35 2017 - [info] Waiting until all relay logs are applied.
Wed May 24 19:44:35 2017 - [info] done.
Wed May 24 19:44:35 2017 - [info] Getting slave status..
Wed May 24 19:44:35 2017 - [info] This slave(192.168.244.20)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000002:120). No need to recover from Exec_Master_Log_Pos.Wed May 24 19:44:35 2017 - [info] Connecting to the target slave host 192.168.244.20, running recover script..
Wed May 24 19:44:35 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.168.244.20 --slave_ip=192.168.244.20 --slave_port=3306 --apply_files=/tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170524194420 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxxWed May 24 19:44:35 2017 - [info]
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/saved_master_binlog_from_192.168.244.10_3306_20170524194420.binlog on 192.168.244.20:3306. This may take long time...Applying log files succeeded.
Wed May 24 19:44:35 2017 - [info] All relay logs were successfully applied.
Wed May 24 19:44:35 2017 - [info] Resetting slave 192.168.244.20(192.168.244.20:3306) and starting replication from the new master 192.168.244.30(192.168.244.30:3306)..Wed May 24 19:44:35 2017 - [info] Executed CHANGE MASTER.
Wed May 24 19:44:35 2017 - [info] Slave started.
Wed May 24 19:44:35 2017 - [info] End of log messages from 192.168.244.20.
Wed May 24 19:44:35 2017 - [info] -- Slave recovery on host 192.168.244.20(192.168.244.20:3306) succeeded.
Wed May 24 19:44:35 2017 - [info] All new slave servers recovered successfully.
Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:35 2017 - [info] * Phase 5: New master cleanup phase..
Wed May 24 19:44:35 2017 - [info]
Wed May 24 19:44:35 2017 - [info] Resetting slave info on the new master..
Wed May 24 19:44:35 2017 - [info] 192.168.244.30: Resetting slave info succeeded.
Wed May 24 19:44:35 2017 - [info] Master failover to 192.168.244.30(192.168.244.30:3306) completed successfully.
Wed May 24 19:44:35 2017 - [info]
----- Failover Report -----app1: MySQL Master failover 192.168.244.10(192.168.244.10:3306) to 192.168.244.30(192.168.244.30:3306) succeeded
Master 192.168.244.10(192.168.244.10:3306) is down!Check MHA Manager logs at node4 for details.
Started manual(interactive) failover.
Invalidated master IP address on 192.168.244.10(192.168.244.10:3306)
The latest slave 192.168.244.20(192.168.244.20:3306) has all relay logs for recovery.
Selected 192.168.244.30(192.168.244.30:3306) as a new master.192.168.244.30(192.168.244.30:3306): OK: Applying all logs succeeded.192.168.244.30(192.168.244.30:3306): OK: Activated master IP address.192.168.244.20(192.168.244.20:3306): This host has the latest relay log events.
Generating relay diff files from the latest slave succeeded.192.168.244.20(192.168.244.20:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.244.30(192.168.244.30:3306)192.168.244.30(192.168.244.30:3306): Resetting slave info succeeded.
Master failover to 192.168.244.30(192.168.244.30:3306) completed successfully.
Wed May 24 19:44:35 2017 - [info] Sending mail..
Unknown option: conf
在切換的過程中，會有兩次確認(rèn)操作。
通過日志的輸出，可以看出，手動(dòng)Failover的切換邏輯和自動(dòng)Failover的切換邏輯基本一致。
在上面的命令中，顯示指定了--new_master_host參數(shù)，如果，沒有顯示指定該參數(shù)的話，則默認(rèn)新主為192.168.244.20，因?yàn)樵?etc/masterha/app1.cnf中將主機(jī)設(shè)置為candidate_master=1。
事實(shí)上，如果master alive的話，是不允許切換的。
Wed May 24 19:26:24 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed May 24 19:26:24 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Wed May 24 19:26:24 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Wed May 24 19:26:24 2017 - [info] MHA::MasterFailover version 0.56.
Wed May 24 19:26:24 2017 - [info] Starting master failover.
Wed May 24 19:26:24 2017 - [info]
Wed May 24 19:26:24 2017 - [info] * Phase 1: Configuration Check Phase..
Wed May 24 19:26:24 2017 - [info]
Wed May 24 19:26:26 2017 - [info] GTID failover mode = 0Wed May 24 19:26:26 2017 - [info] Dead Servers:
Wed May 24 19:26:26 2017 - [error][/usr/local/share/perl5/MHA/MasterFailover.pm, ln187] None of server is dead. Stop failover.
Wed May 24 19:26:26 2017 - [error][/usr/local/share/perl5/MHA/ManagerUtil.pm, ln177] Got ERROR: at /usr/local/bin/masterha_master_switch line 53.
View Code
在默認(rèn)情況下，如果MHA檢測到兩次切換的時(shí)間小于8小時(shí)，則不允許進(jìn)行Failover，這個(gè)時(shí)候，需指定--ignore_last_failover參數(shù)
# masterha_master_switch --master_state=dead --conf=/etc/masterha/app1.cnf --dead_master_host=192.168.244.10 --dead_master_port=3306--dead_master_ip=<dead_master_ip> is not set. Using 192.168.244.10.
Wed May 24 19:26:24 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed May 24 19:26:24 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Wed May 24 19:26:24 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Wed May 24 19:26:24 2017 - [info] MHA::MasterFailover version 0.56.
Wed May 24 19:26:24 2017 - [info] Starting master failover.
Wed May 24 19:26:24 2017 - [info]
Wed May 24 19:26:24 2017 - [info] * Phase 1: Configuration Check Phase..
Wed May 24 19:26:24 2017 - [info]
Wed May 24 19:26:26 2017 - [info] GTID failover mode = 0Wed May 24 19:26:26 2017 - [info] Dead Servers:
Wed May 24 19:26:26 2017 - [error][/usr/local/share/perl5/MHA/MasterFailover.pm, ln187] None of server is dead. Stop failover.
Wed May 24 19:26:26 2017 - [error][/usr/local/share/perl5/MHA/ManagerUtil.pm, ln177] Got ERROR: at /usr/local/bin/masterha_master_sw
itch line 53.[root@node4 ~]# masterha_master_switch --master_state=dead --conf=/etc/masterha/app1.cnf --dead_master_host=192.168.244.10 --dead_mas
ter_port=3306--dead_master_ip=<dead_master_ip> is not set. Using 192.168.244.10.
Wed May 24 19:29:23 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed May 24 19:29:23 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Wed May 24 19:29:23 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Wed May 24 19:29:23 2017 - [info] MHA::MasterFailover version 0.56.
Wed May 24 19:29:23 2017 - [info] Starting master failover.
Wed May 24 19:29:23 2017 - [info]
Wed May 24 19:29:23 2017 - [info] * Phase 1: Configuration Check Phase..
Wed May 24 19:29:23 2017 - [info]
Wed May 24 19:29:24 2017 - [info] GTID failover mode = 0Wed May 24 19:29:24 2017 - [info] Dead Servers:
Wed May 24 19:29:24 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:29:24 2017 - [info] Checking master reachability via MySQL(double check)...
Wed May 24 19:29:24 2017 - [info] ok.
Wed May 24 19:29:24 2017 - [info] Alive Servers:
Wed May 24 19:29:24 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Wed May 24 19:29:24 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Wed May 24 19:29:24 2017 - [info] Alive Slaves:
Wed May 24 19:29:24 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:29:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Wed May 24 19:29:24 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Wed May 24 19:29:24 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabledWed May 24 19:29:24 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Master 192.168.244.10(192.168.244.10:3306) is dead. Proceed? (yes/NO): yes
Wed May 24 19:29:46 2017 - [error][/usr/local/share/perl5/MHA/MasterFailover.pm, ln309] Last failover was done at 2017/05/24 16:04:54. Current time is too early to do failover again. If you want to do failover, manually remove /masterha/app1/app1.failover.complete and run this script again.Wed May 24 19:29:46 2017 - [error][/usr/local/share/perl5/MHA/ManagerUtil.pm, ln177] Got ERROR: at /usr/local/bin/masterha_master_sw
itch line 53.
View Code
后面附上之前提到的測試結(jié)果不理想的兩種方案
方案一：
模擬步驟如下：
1. master上創(chuàng)建測試表
mysql sbtest.t1(id ,col1 (),col2 (),col3 (),col4 (),col5 ),col6 (),col7 (),col8 (),col9 (),col10 ());
Query OK, rows affected ( sec)
2. 關(guān)閉Candicate master和Slave的主從復(fù)制。
mysql> stop slave;
Query OK, 0 rows affected (0.03 sec)
3. 在master上生成測試數(shù)據(jù)
創(chuàng)建存儲過程
delimiter //create procedure p1()begin
declare v1 int default 0; while v1 <=700000 do insert into sbtest.t1 values(v1,'aaaaaaaaaa','bbbbbbbbbb','cccccccccc','dddddddddd','eeeeeeeeee','ffffffffff','gggggggggg','hhhhhhhhhh','iiiiiiiiii','jjjjjjjjjj'); set v1=v1+1; if v1 %1000 =0 then
commit; end if; end while;end//delimiter ;
執(zhí)行存儲過程
mysql> call p1;
共執(zhí)行了兩次，生成了500M左右的binlog
[root@node1 ~]# ll -h /var/lib/mysql/mysql-bin.000046 -rw-rw---- 1 mysql mysql 502M Apr 24 15:18 /var/lib/mysql/mysql-bin.00004
5. 開啟Candicate master和Slave的主從復(fù)制并kill掉master的mysqld進(jìn)程，模擬主庫發(fā)生故障，進(jìn)行自動(dòng)failover操作
在這里，我寫了個(gè)腳本來實(shí)現(xiàn)開啟slave復(fù)制并kill掉master mysqld進(jìn)程的功能
# vim monitor_slave.py
= MySQLdb.connect(host, , === slave_status_result[10], slave_status_result[11= [, == CheckSlaveStatus(check_host[1 check_slave_status
= slave_status == [, 510 == subprocess.Popen(command_line, stdout=subprocess.PIPE, shell= ==
執(zhí)行該腳本
6. 查看MHA的切換日志
Sun May 21 09:46:56 2017 - [warning] Got error on MySQL select ping: 2006 (MySQL server has gone away)
Sun May 21 09:46:56 2017 - [info] Executing secondary network check script: /usr/local/bin/masterha_secondary_check -s 192.168.244.20 -s 192.168.244.30 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --master_user=monitor --masteConnection timed out during banner exchange
Sun May 21 09:47:08 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Sun May 21 09:47:08 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Sun May 21 09:47:08 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 09:46:57 2017 - [warning] Connection failed 2 time(s)..
Sun May 21 09:46:58 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 09:46:58 2017 - [warning] Connection failed 3 time(s)..
Sun May 21 09:46:59 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Sun May 21 09:46:59 2017 - [warning] Connection failed 4 time(s)..
Monitoring server 192.168.244.20 is reachable, Master is not reachable from 192.168.244.20. OK.
Sun May 21 09:47:01 2017 - [warning] HealthCheck: SSH to 192.168.244.10 is NOT reachable.
Monitoring server 192.168.244.30 is reachable, Master is not reachable from 192.168.244.30. OK.
Sun May 21 09:47:07 2017 - [info] Master is not reachable from all other monitoring servers. Failover should start.
Sun May 21 09:47:07 2017 - [warning] Master is not reachable from health checker!Sun May 21 09:47:07 2017 - [warning] Master 192.168.244.10(192.168.244.10:3306) is not reachable!Sun May 21 09:47:07 2017 - [warning] SSH is NOT reachable.
Sun May 21 09:47:07 2017 - [info] Connecting to a master server failed. Reading configuration file /etc/masterha_default.cnf and /etc/masterha/app1.cnf again, and trying to connect to all servers to check server status..
Sun May 21 09:47:07 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Sun May 21 09:47:07 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
Sun May 21 09:47:07 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..
Sun May 21 09:47:08 2017 - [info] GTID failover mode = 0Sun May 21 09:47:08 2017 - [info] Dead Servers:
Sun May 21 09:47:08 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:08 2017 - [info] Alive Servers:
Sun May 21 09:47:08 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Sun May 21 09:47:08 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Sun May 21 09:47:08 2017 - [info] Alive Slaves:
Sun May 21 09:47:08 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:08 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:08 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:08 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:08 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:08 2017 - [info] Checking slave configurations..
Sun May 21 09:47:08 2017 - [info] Checking replication filtering settings..
Sun May 21 09:47:08 2017 - [info] Replication filtering check ok.
Sun May 21 09:47:08 2017 - [info] Master is down!Sun May 21 09:47:08 2017 - [info] Terminating monitoring script.
Sun May 21 09:47:08 2017 - [info] Got exit code 20 (Master dead).
Sun May 21 09:47:08 2017 - [info] MHA::MasterFailover version 0.56.
Sun May 21 09:47:08 2017 - [info] Starting master failover.
Sun May 21 09:47:08 2017 - [info]
Sun May 21 09:47:08 2017 - [info] * Phase 1: Configuration Check Phase..
Sun May 21 09:47:08 2017 - [info]
Sun May 21 09:47:09 2017 - [info] GTID failover mode = 0Sun May 21 09:47:09 2017 - [info] Dead Servers:
Sun May 21 09:47:09 2017 - [info] 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Checking master reachability via MySQL(double check)...
Sun May 21 09:47:09 2017 - [info] ok.
Sun May 21 09:47:09 2017 - [info] Alive Servers:
Sun May 21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306)
Sun May 21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306)
Sun May 21 09:47:09 2017 - [info] Alive Slaves:
Sun May 21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Starting Non-GTID based failover.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] ** Phase 1: Configuration Check Phase completed.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 2: Dead Master Shutdown Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] Forcing shutdown so that applications never connect to the current master..
Sun May 21 09:47:09 2017 - [info] Executing master IP deactivation script:
Sun May 21 09:47:09 2017 - [info] /usr/local/bin/master_ip_failover --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --command=stop
Disabling the VIP an old master: 192.168.244.10 Sun May 21 09:47:09 2017 - [info] done.
Sun May 21 09:47:09 2017 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Sun May 21 09:47:09 2017 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3: Master Recovery Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] The latest binary log file/position on all slaves is mysql-bin.000001:37651149Sun May 21 09:47:09 2017 - [info] Latest slaves (Slaves that received relay log files to the latest):
Sun May 21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:09 2017 - [info] The oldest binary log file/position on all slaves is mysql-bin.000001:35083093Sun May 21 09:47:09 2017 - [info] Oldest slaves:
Sun May 21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [warning] Dead Master is not SSH reachable. Could not save it's binlogs. Transactions that were not sent to the latest slave (Read_Master_Log_Pos to the tail of the dead master's binlog) were lost.
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] * Phase 3.3: Determining New Master Phase..
Sun May 21 09:47:09 2017 - [info]
Sun May 21 09:47:09 2017 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Sun May 21 09:47:10 2017 - [info] HealthCheck: SSH to 192.168.244.20 is reachable.
Sun May 21 09:47:10 2017 - [info] Checking whether 192.168.244.20 has relay logs from the oldest position..
Sun May 21 09:47:10 2017 - [info] Executing command: apply_diff_relay_logs --command=find --latest_mlf=mysql-bin.000001 --latest_rmlp=37651149 --target_mlf=mysql-bin.000001 --target_rmlp=35083093 --server_id=2 --workdir=/tmp --timestamp=20170521094708 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/ :
Opening /var/lib/mysql/relay-log.info ... ok.
Relay log found at /var/lib/mysql, up to mysqld-relay-bin.000004
Fast relay log position search succeeded.
Target relay log file/position found. start_file:mysqld-relay-bin.000004, start_pos:35083256.
Target relay log FOUND!Sun May 21 09:47:11 2017 - [info] OK. 192.168.244.20 has all relay logs.
Sun May 21 09:47:11 2017 - [info] HealthCheck: SSH to 192.168.244.30 is reachable.
Sun May 21 09:47:13 2017 - [info] Searching new master from slaves..
Sun May 21 09:47:13 2017 - [info] Candidate masters from the configuration file:
Sun May 21 09:47:13 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled
Sun May 21 09:47:13 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)
Sun May 21 09:47:13 2017 - [info] Primary candidate for the new Master (candidate_master is set)
Sun May 21 09:47:13 2017 - [info] Non-candidate masters:
Sun May 21 09:47:13 2017 - [info] Searching from candidate_master slaves which have received the latest relay log events..
Sun May 21 09:47:13 2017 - [info] New master is 192.168.244.20(192.168.244.20:3306)
Sun May 21 09:47:13 2017 - [info] Starting master failover..
Sun May 21 09:47:13 2017 - [info]
From:192.168.244.10(192.168.244.10:3306) (current master) +--192.168.244.20(192.168.244.20:3306) +--192.168.244.30(192.168.244.30:3306)
To:192.168.244.20(192.168.244.20:3306) (new master) +--192.168.244.30(192.168.244.30:3306)
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] * Phase 3.4: Master Log Apply Phase..
Sun May 21 09:47:13 2017 - [info]
Sun May 21 09:47:13 2017 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Sun May 21 09:47:13 2017 - [info] Starting recovery on 192.168.244.20(192.168.244.20:3306)..
Sun May 21 09:47:13 2017 - [info] This server has all relay logs. Waiting all logs to be applied..
Sun May 21 09:47:56 2017 - [info] done.
Sun May 21 09:47:56 2017 - [info] All relay logs were successfully applied.
Sun May 21 09:47:56 2017 - [info] Getting new master's binlog name and position..Sun May 21 09:47:56 2017 - [info] mysql-bin.000010:166054508Sun May 21 09:47:56 2017 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.244.20', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000010', MASTER_LOG_POS=166054508, MASTER_USER='repl', MASTER_PASSWORD='xxx';
Sun May 21 09:47:56 2017 - [info] Executing master IP activate script:
Sun May 21 09:47:56 2017 - [info] /usr/local/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --new_master_host=192.168.244.20 --new_master_ip=192.168.244.20 --new_master_port=3306 --new_master_user='monitor' --new_master_password='monitor123' Set read_only=0 on the new master.
Enabling the VIP 192.168.244.188 on the new master: 192.168.244.20 Sun May 21 09:47:59 2017 - [info] OK.
Sun May 21 09:47:59 2017 - [info] ** Finished master recovery successfully.
Sun May 21 09:47:59 2017 - [info] * Phase 3: Master Recovery Phase completed.
Sun May 21 09:47:59 2017 - [info]
Sun May 21 09:47:59 2017 - [info] * Phase 4: Slaves Recovery Phase..
Sun May 21 09:47:59 2017 - [info]
Sun May 21 09:47:59 2017 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Sun May 21 09:47:59 2017 - [info]
Sun May 21 09:47:59 2017 - [info] -- Slave diff file generation on host 192.168.244.30(192.168.244.30:3306) started, pid: 3606. Check tmp log /masterha/app1/192.168.244.30_3306_20170521094708.log if it takes time..
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:48:04 2017 - [info] Log messages from 192.168.244.30 ...
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:47:59 2017 - [info] Server 192.168.244.30 received relay logs up to: mysql-bin.000001:35083093Sun May 21 09:47:59 2017 - [info] Need to get diffs from the latest slave(192.168.244.20) up to: mysql-bin.000001:37651149 (using the latest slave's relay logs)Sun May 21 09:47:59 2017 - [info] Connecting to the latest slave host 192.168.244.20, generating diff relay log files..
Sun May 21 09:47:59 2017 - [info] Executing command: apply_diff_relay_logs --command=generate_and_send --scp_user=root --scp_host=192.168.244.30 --latest_mlf=mysql-bin.000001 --latest_rmlp=37651149 --target_mlf=mysql-bin.000001 --target_rmlp=35083093 --server_id=2 --diff_file_readtolatest=/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog --workdir=/tmp --timestamp=20170521094708 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/ Sun May 21 09:48:04 2017 - [info]
Opening /var/lib/mysql/relay-log.info ... ok.
Relay log found at /var/lib/mysql, up to mysqld-relay-bin.000004
Fast relay log position search succeeded.
Target relay log file/position found. start_file:mysqld-relay-bin.000004, start_pos:35083256.
Concat binary/relay logs from mysqld-relay-bin.000004 pos 35083256 to mysqld-relay-bin.000004 EOF into /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog ..
Binlog Checksum enabled
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 283.. ok.
Dumping effective binlog data from /var/lib/mysql/mysqld-relay-bin.000004 position 35083256 to tail(37651312).. ok.
Binlog Checksum enabled
Binlog Checksum enabled
Concat succeeded.
Generating diff relay log succeeded. Saved at /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog . scp node2:/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog to root@192.168.244.30(22) succeeded.
Sun May 21 09:48:04 2017 - [info] Generating diff files succeeded.
Sun May 21 09:48:04 2017 - [info] End of log messages from 192.168.244.30.
Sun May 21 09:48:04 2017 - [info] -- Slave diff log generation on host 192.168.244.30(192.168.244.30:3306) succeeded.
Sun May 21 09:48:04 2017 - [info] Generating relay diff files from the latest slave succeeded.
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:48:04 2017 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Sun May 21 09:48:04 2017 - [info]
Sun May 21 09:48:04 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) started, pid: 3613. Check tmp log /masterha/app1/192.168.244.30_3306_20170521094708.log if it takes time..
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:12 2017 - [info] Log messages from 192.168.244.30 ...
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:04 2017 - [info] Starting recovery on 192.168.244.30(192.168.244.30:3306)..
Sun May 21 09:48:04 2017 - [info] Generating diffs succeeded.
Sun May 21 09:48:04 2017 - [info] Waiting until all relay logs are applied.
Sun May 21 09:48:04 2017 - [info] done.
Sun May 21 09:48:04 2017 - [info] Getting slave status..
Sun May 21 09:48:04 2017 - [info] This slave(192.168.244.30)'s Exec_Master_Log_Pos(mysql-bin.000001:35083010) does not equal to Read_Master_Log_Pos(mysql-bin.000001:35083093). It is likely that relay log was cut during transaction. Need to recover from Exec_Master_Log_Pos.Sun May 21 09:48:04 2017 - [info] Saving local relay logs from exec pos to read pos on 192.168.244.30: from mysqld-relay-bin.000004:35083173 to the end of the relay log..
Sun May 21 09:48:04 2017 - [info] Executing command : save_binary_logs --command=save --start_file=mysqld-relay-bin.000004 --start_pos=35083173 --output_file=/tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --binlog_dir=/var/lib/mysql/ Sun May 21 09:48:05 2017 - [info]
Creating /tmp if not exists.. ok.
Concat binary/relay logs from mysqld-relay-bin.000004 pos 35083173 to mysqld-relay-bin.000004 EOF into /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog ..
Binlog Checksum enabled
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 283.. ok.
Dumping effective binlog data from /var/lib/mysql/mysqld-relay-bin.000004 position 35083173 to tail(35083256).. ok.
Binlog Checksum enabled
Binlog Checksum enabled
Concat succeeded.
Sun May 21 09:48:05 2017 - [info] Connecting to the target slave host 192.168.244.30, running recover script..
Sun May 21 09:48:05 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.168.244.30 --slave_ip=192.168.244.30 --slave_port=3306 --apply_files=/tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog,/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170521094708 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx
Sun May 21 09:48:12 2017 - [info]
Concat all apply files to /tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog ..
Copying the first binlog file /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog to /tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog.. ok.
Dumping binlog head events (rotate events), skipping format description events from /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog.. Binlog Checksum enabled
Binlog Checksum enabled
dumped up to pos 283. ok. /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog has effective binlog events from pos 283.
Dumping effective binlog data from /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog position 283 to tail(2568339).. ok.
Concat succeeded.
All apply target binary logs are concatinated at /tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog .
MySQL client version is 5.6.31. Using --binary-mode.
Applying differential binary/relay log files /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog,/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog on 192.168.244.30:3306. This may take long time...
Applying log files succeeded.
Sun May 21 09:48:12 2017 - [info] All relay logs were successfully applied.
Sun May 21 09:48:12 2017 - [info] Resetting slave 192.168.244.30(192.168.244.30:3306) and starting replication from the new master 192.168.244.20(192.168.244.20:3306)..
Sun May 21 09:48:12 2017 - [info] Executed CHANGE MASTER.
Sun May 21 09:48:12 2017 - [info] Slave started.
Sun May 21 09:48:12 2017 - [info] End of log messages from 192.168.244.30.
Sun May 21 09:48:12 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) succeeded.
Sun May 21 09:48:12 2017 - [info] All new slave servers recovered successfully.
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:12 2017 - [info] * Phase 5: New master cleanup phase..
Sun May 21 09:48:12 2017 - [info]
Sun May 21 09:48:12 2017 - [info] Resetting slave info on the new master..
Sun May 21 09:48:12 2017 - [info] 192.168.244.20: Resetting slave info succeeded.
Sun May 21 09:48:12 2017 - [info] Master failover to 192.168.244.20(192.168.244.20:3306) completed successfully.
Sun May 21 09:48:12 2017 - [info] Deleted server1 entry from /etc/masterha/app1.cnf .
Sun May 21 09:48:12 2017 - [info]
----- Failover Report -----app1: MySQL Master failover 192.168.244.10(192.168.244.10:3306) to 192.168.244.20(192.168.244.20:3306) succeeded
Master 192.168.244.10(192.168.244.10:3306) is down!Check MHA Manager logs at node4:/masterha/app1/manager.log for details.
Started automated(non-interactive) failover.
Invalidated master IP address on 192.168.244.10(192.168.244.10:3306)
The latest slave 192.168.244.20(192.168.244.20:3306) has all relay logs for recovery.
Selected 192.168.244.20(192.168.244.20:3306) as a new master.192.168.244.20(192.168.244.20:3306): OK: Applying all logs succeeded.192.168.244.20(192.168.244.20:3306): OK: Activated master IP address.192.168.244.30(192.168.244.30:3306): Generating differential relay logs up to 192.168.244.20(192.168.244.20:3306)succeeded.
Generating relay diff files from the latest slave succeeded.192.168.244.30(192.168.244.30:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.244.20(192.168.244.20:3306)192.168.244.20(192.168.244.20:3306): Resetting slave info succeeded.
Master failover to 192.168.244.20(192.168.244.20:3306) completed successfully.
Sun May 21 09:48:12 2017 - [info] Sending mail..
Unknown option: conf
View Code
方案二
對Candicate master上和Slave上的網(wǎng)卡進(jìn)行帶寬限制
Candicate master
[root@node2 ~]# /sbin/tc qdisc add dev eth0 root tbf rate 50kbit latency 50ms burst 15kb
Slave
/sbin/tc qdisc add dev eth0 root tbf rate 80kbit latency 50ms burst 15kb
注意：Candicate master的網(wǎng)卡限制在50kbit，slave的網(wǎng)卡限制在80kbit，
要確保Candicate master的小于slave的，這樣才能模擬出Candicate master上relay log的位置小于slave上relay log的位置。
關(guān)于如何確認(rèn)網(wǎng)卡的速率控制到多大合適，
可通過壓測，測試master的吞吐量，
以及結(jié)合如下方法，測試主機(jī)之間的傳輸速率來確定網(wǎng)卡合適的速率。
[root@node1 ~]# dd if=/dev/zero of=hello.txt bs=100M count=1
[root@node1 ~]# time scp hello.txt 192.168.244.20:/tmp/
hello.txt 100% 100MB 2.6MB/s 00:39
參考
《深入淺出MySQL》
以上就是MHA自動(dòng)Failover與手動(dòng)Failover的切換原理的詳細(xì)內(nèi)容，更多請關(guān)注php中文網(wǎng)其它相關(guān)文章！
學(xué)習(xí)教程快速掌握從入門到精通的SQL知識。
