집 >데이터 베이스 >MySQL 튜토리얼 >MHA 자동 장애 조치(failover)와 수동 장애 조치(failover) 간의 전환 원리
MHA 자동 장애 조치(failover)와 수동 장애 조치(failover) 간의 전환 원리
- 大家讲道理원래의
- 2017-05-28 11:20:382034검색
color 클러스터 정보 i 문자 IP 주소 Serverid 유형
Master 192.168.244.10 1 Write tocandicate Master 192.168.244.20 2 Read Slave 192.168.244.30 3 Reading
Monitor 192.168.244.40 그룹 MHA 특정 건설 단계 및 원칙, 다른 블로그를 참고하세요:MySQL
고가용성 솔루션 MHA Automatic FailoverMHA 로그를 통과하려면 MHA 자동 Failover의 구현 원리를 명확하게 판단하려면 다음 시나리오를 시뮬레이션해야 합니다. 메인 데이터베이스에 장애가 발생하면 마스터의 일부 binlog 로그가 Candicate 마스터 및 슬레이브로 전송되지 않고 Candicate 마스터보다 슬레이브에 더 많은 바이너리 로그가 있습니다.여러 솔루션을 시도한 결과 마침내 원하는 것을 얻었습니다.
옵션 1: 1. Candicate 마스터와 슬레이브의 마스터-슬레이브 복제를 끕니다. 2.저장 프로시저
를 통해 테스트 데이터 생성 3. Candicate 마스터와 슬레이브의 마스터-슬레이브 복제를 활성화하고 마스터의 mysqld 프로세스를 종료하고, 메인 라이브러리의 장애를 시뮬레이션하고, 자동 장애 조치 작업을 수행합니다. 이를 위해 저희도 특별히 스크립트를 작성했지만, 안타깝게도 자동 장애 조치 과정에서 MHA Manager에서 마스터로 "SSH is NOT reach
able"이라는 메시지가 표시됩니다. 옵션 2: tc 명령을 사용하여 Candicate 마스터와 슬레이브의 네트워크 카드에 대해 서로 다른 전송 속도를 설정하여 Candicate 마스터로 전송되는 로그의 양이 슬레이브의 로그 양보다 적도록 합니다. 옵션 3: 마스터-슬레이브 복제에서는 마스터의 mysqld 데이터베이스를 직접 닫습니다. 그러나 이런 방식으로는 Candicate 마스터보다 슬레이브에 더 많은 바이너리 로그가 있다는 효과는 얻을 수 없습니다. 옵션 4: 릴레이 로그를 가로채서 슬레이브를 끄는 방법으로 master.info 및 Relay-log.info의 위치 지점을 수정하여 Candicate 마스터의 로그 볼륨을 슬레이브의 로그 볼륨보다 인위적으로 작게 만듭니다. . 나중에 생각해보면 사실 이 방법은 Candicate 마스터의 마스터-슬레이브 복제를 먼저 닫은 다음, 마스터에서 작업을 수행하고, 슬레이브에서 마스터-슬레이브 복제를 닫은 다음, 다음과 같은 작업을 수행하는 것과 같습니다. 마스터에서 작업. 이렇게 하면 마스터의 binlog > 슬레이브의 릴레이 로그 > 후보 마스터의 릴레이 로그가 구현됩니다. 옵션 4가 드디어 원하는 결과를 얻었습니다 옵션 4를 통해 MHA의 구현 원리를 살펴보겠습니다 1. 테스트 테이블 생성 및 테스트 데이터 삽입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 마스터의 binlog 내용과 슬레이브의 릴레이 로그 내용을 각각 봅니다.
Pass 마스터의 binlog 이벤트를 비교하면 show Relaylog 이벤트에서 End_log_pos가 실제로 binlog에서 해당 바이너리
의 위치를 참조하는 것을 볼 수 있습니다.
다시 Candicate 마스터에서 해당 릴레이 로그 내용을 확인해 보겠습니다 [root@node2 mysql]# mysqlbinlog mysqld-relay-bin.000002
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)
mysql中binlog有个有意思的地方是，位置点其实是也是字节的大小。
譬如，上面这个relay log中，最后一个位点是# at 1440，算上最后一个commit操作需占用31个字节，所以整个文件的大小是1471，与实际大小吻合。
[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的值。
虽然这几个参数的值与master.info和relay-log.info文件是相对应的，
但通过修改master.info和relay-log.info的值，并重启slave，并不会将上述几个参数值修改。
上述几个参数是保存到内存中的，唯一可行的方案是首先关闭slave实例，再修改master.info和relay-log.info文件，然后重新启动mysql实例。
4. 关闭Candicate master实例，剪裁relay log，修改master.info和relay-log.info文件。
关闭实例
[root@node2 mysql]# service mysqld stop
剪裁relay log
这里，写了个python脚本实现该功能
#!/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对应的是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的内容
主要是修改第三行
23mysql-bin.0000011308
修改为
23mysql-bin.000001452
修改relay-log.info的内容
原文件如下：
7./mysqld-relay-bin.0000021471mysql-bin.0000011308001
修改为：
7./mysqld-relay-bin.000002615mysql-bin.000001452001
启动slave，注意，配置文件中必须设置skip-slave-start，不然它自动开启主从复制。
[root@node2 mysql]# service mysqld start
5. 对于slave，同样如此处理，只不过relay log的位置点要靠后些
#!/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对应的是insert into sbtest.b values(3,'c')这条记录
修改master.info的内容
23mysql-bin.000001 880
修改relay-log.info的内容
7./mysqld-relay-bin.000002 1043mysql-bin.000001 8800 01
6. 开启MHA监控
# 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. 关闭master实例
# service mysqld stop
8. 查看MHA切换日志，了解整个切换过程。
该日志的时间点与上面relay log的时间点并不吻合，原因在于这个反复测试了很多次。
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.-- 当monitor检测到master mysqld不可用的时候，即根据masterha_secondary_check脚本从Candicate master和Slave上判断master mysqld的可用性， 根据上面的显示信息，通过192.168.244.20和192.168.244.30也判断到master mysqld不可用。 如果任意一个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主机通过ssh还是能登录上去。 如果这里显示的是SSH is NOT reachable，则代表master主机也已经宕机了， 刚开始还以为是通过ssh来判断主机是否宕机，但在之前的测试方案中（具体可见文末），master并没有宕机，这里却显示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的相关配置，比如read_only参数，是否设置了复制的过滤规则 从上面的输出中可以看出，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的可用性。 第二阶段，关闭dead master。 包括执行摘除master上的vip，同时执行shutdown_script脚本，因为该脚本在配置文件中没有定义，故跳过。 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 判断哪个slave的二进制日志是最新的。 通过下面的输出可以看出，所有的slave中，最新的二进制日志位置是mysql-bin.000001:880（通过show slave status中的Master_Log_File, Read_Master_Log_Pos得到） 最旧的二进制日志位置是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 注意，上面已经判断到slave中最新二进制日志是mysql-bin.000001:880，所以它把该位置后所有二进制日志都拼接起来，并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中是否包括最旧的二进制日志（mysql-bin.000001:452）以后的relay log。 接着选新主， 因为192.168.244.20中设置了candidate_master设置了，所以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 获取新主所需的差异二进制日志，包括两部分 1> 新主和最新的slave之间差异的relay log 2> 保存在MHA Manager上的最新的slave和原master之前差异的binlog 其中，差异的relay log通过如下方式获取： ssh到192.168.244.30上，执行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 应用从master保存的二进制日志事件 首先，等原来的所有的relay log都应用完。 其次，再通过apply_diff_relay_logs应用差异的relay log，及差异的binlog。 应用完毕后，得到新的master binlog的文件和位置，其它slave可根据该文件和位置来建立主从复制关系。 第三，执行master_ip_failover脚本，执行如下操作 1> 将新主的read_only设置为0 2> 启动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恢复阶段-- 4.1 因为192.168.244.30拥有最新的relay log，所以也没必要获取差异的relay log-- 4.2 开始slave的恢复阶段 1> 将monitor上保存的master上的差异的二进制日志scp到slave上。 2> 应用差异日志。 3> 清除原来的复制关系，并再次执行change master命令建立新的主从同步。 如果有多个slave，则该恢复过程是并行的。 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 报告，发送告警邮件----- 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
从上面的日志输出可以看出整个MHA的切换过程
首先，MHA Manager检测到master不可用，则会通过另外两个slave检查master的可用性。一共检测4次。
同时判断MHA Manager到master的ssh可用性。
ssh可用性的判断结果影响后后续切换中的“Phase 3.2: Saving Dead Master's Binlog Phase”
Phase 1: Configuration Check Phase..
检查了MHA的配置信息，并再次判断了master的可用性。
Phase 2: Dead Master Shutdown Phase..
宕机的master处理阶段，包括摘除VIP，执行shutdown_script中定义的脚本。
Phase 3: Master Recovery Phase..
Phase 3.1: Getting Latest Slaves Phase..
判断哪个slave拥有最新的relay log（通过比较show slave status中的Master_Log_File, Read_Master_Log_Pos位置），
哪个slave拥有最旧的relay log
Phase 3.2: Saving Dead Master's Binlog Phase..
根据上面得到的slave的最新位置信息，将差异的二进制日志保存到MHA Manager的指定目录下。
如果在第一步骤中，判断了MHA Manager到master的ssh不可用，则会跳过这个阶段。
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都应用完。
其次，通过apply_diff_relay_logs应用差异的relay log，及差异的binlog。
应用完毕后，得到新的master binlog的文件和位置，其它slave可根据该文件和位置来建立主从复制关系。
第三，执行master_ip_failover脚本，执行如下操作
1> 将新主的read_only设置为0
2> 启动vip
Phase 4: Slaves Recovery Phase
Phase 4.1: Starting Parallel Slave Diff Log Generation Phase
为slave获取差异的relay log
因为192.168.244.30拥有最新的relay log，所以也没必要获取差异的relay log
Phase 4.2: Starting Parallel Slave Log Apply Phase
开始slave的恢复阶段
1> 将差异的relay log和master差异日志scp到slave上。
2> 应用差异日志。
3> 清除原来的复制关系，并再次执行change master命令建立新的主从同步。
如果有多个slave，则该恢复过程是并行的。
Phase 5: New master cleanup phase
从MHA的配置文件中剔除server1的配置信息
最后，生成Failover Report并发送告警邮件。
手动Failover
与自动Failover相对应的是手动Failover，即当master发生故障时，通过手动执行脚本来进行故障切换。
命令如下：
# 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
在切换的过程中，会有两次确认操作。
通过日志的输出，可以看出，手动Failover的切换逻辑和自动Failover的切换逻辑基本一致。
在上面的命令中，显示指定了--new_master_host参数，如果，没有显示指定该参数的话，则默认新主为192.168.244.20，因为在/etc/masterha/app1.cnf中将主机设置为candidate_master=1。
事实上，如果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
在默认情况下，如果MHA检测到两次切换的时间小于8小时，则不允许进行Failover，这个时候，需指定--ignore_last_failover参数
# 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
后面附上之前提到的测试结果不理想的两种方案
方案一：
模拟步骤如下：
1. master上创建测试表
mysql sbtest.t1(id ,col1 (),col2 (),col3 (),col4 (),col5 ),col6 (),col7 (),col8 (),col9 (),col10 ()); Query OK, rows affected ( sec)
2. 关闭Candicate master和Slave的主从复制。
mysql> stop slave; Query OK, 0 rows affected (0.03 sec)
3. 在master上生成测试数据
创建存储过程
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 ;执行存储过程
mysql> call p1;
共执行了两次，生成了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的主从复制并kill掉master的mysqld进程，模拟主库发生故障，进行自动failover操作
在这里，我写了个脚本来实现开启slave复制并kill掉master mysqld进程的功能
# 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= ==
执行该脚本
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上的网卡进行带宽限制
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的网卡限制在50kbit，slave的网卡限制在80kbit，
要确保Candicate master的小于slave的，这样才能模拟出Candicate master上relay log的位置小于slave上relay log的位置。
关于如何确认网卡的速率控制到多大合适，
可通过压测，测试master的吞吐量，
以及结合如下方法，测试主机之间的传输速率来确定网卡合适的速率。
[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 자동 장애 조치(failover)와 수동 장애 조치(failover) 간의 전환 원리의 상세 내용입니다. 자세한 내용은 PHP 중국어 웹사이트의 기타 관련 기사를 참조하세요!
성명：
본 글의 내용은 네티즌들의 자발적인 기여로 작성되었으며, 저작권은 원저작자에게 있습니다. 본 사이트는 이에 상응하는 법적 책임을 지지 않습니다. 표절이나 침해가 의심되는 콘텐츠를 발견한 경우 admin@php.cn으로 문의하세요.