Mysqlmaster Switch Log Analysis sample

Here is the MHA from boot, to failover's complete manager.log, and all of the MySQL General.log in the cluster. We can learn more about the workings of MHA through these logs. There is a lot of help in using good MHA.
The architecture is as follows:
DB1 MASTER
DB2 Slave,candidate_master
DB3 SLAVE

DB1:

[Root@localhost mysql]# Cat/var/lib/mysql/localhost.log

140928 10:17:04 5 Connect mha@192.168.153.150 on


5 Query Set Autocommit=1


5 Query SELECT connection_id () as Value


6 Connect mha@192.168.153.150 on


6 Query Set Autocommit=1


6 Query SELECT connection_id () as Value


6 Query SET wait_timeout=86400


6 Query SELECT @ @global. server_id as Value


6 Query SELECT VERSION () as Value


6 Query show GLOBAL VARIABLES like ' Log_bin '


6 Query Show MASTER STATUS


6 Query SELECT @ @global. relay_log_info_repository as Value


6 Query SELECT @ @global. DataDir as Value


6 Query SELECT @ @global. Relay_log_info_file as Value


6 Query SELECT @ @global. DataDir as Value


6 Query Show SLAVE STATUS


6 Query SELECT @ @global. read_only as Value


6 Query SELECT @ @global. Relay_log_purge as Value


140928 10:17:11 7 Connect mha@192.168.153.150 on


7 Query SELECT @ @version_comment Limit 1


7 Query Select COUNT (*) as C from Mysql.user


6 Quit


7 Quit


8 Connect mha@192.168.153.150 on


8 Query Set Autocommit=1


8 Query SET wait_timeout=6


8 Query SELECT get_lock (' mha_master_high_availability_monitor ', ' ') as Value


8 Query SELECT 1 as Value


140928 10:17:14 8 Query SELECT 1 as Value


140928 10:17:17 8 Query SELECT 1 as Value


140928 10:17:20 8 Query SELECT 1 as Value


140928 10:17:23 8 Query SELECT 1 as Value


140928 10:17:26 8 Query SELECT 1 as Value


140928 10:17:29 8 Query SELECT 1 as Value


140928 10:17:32 8 Query SELECT 1 as Value


140928 10:17:35 8 Query SELECT 1 as Value


140928 10:17:38 8 Query SELECT 1 as Value


DB2:

[Root@localhost mysql]# Cat/var/lib/mysql/localhost.log

140928 10:17:04 214 Connect mha@192.168.153.150 on


214 Query Set Autocommit=1


214 Query SELECT connection_id () as Value


215 Connect mha@192.168.153.150 on


215 Query Set Autocommit=1


215 Query SELECT connection_id () as Value


215 Query SET wait_timeout=86400


215 Query SELECT @ @global. server_id as Value


215 Query SELECT VERSION () as Value


215 Query show GLOBAL VARIABLES like ' Log_bin '


215 Query Show MASTER STATUS


215 Query SELECT @ @global. relay_log_info_repository as Value


215 Query SELECT @ @global. DataDir as Value


215 Query SELECT @ @global. Relay_log_info_file as Value


215 Query SELECT @ @global. DataDir as Value


215 Query Show SLAVE STATUS


215 Query SELECT @ @global. read_only as Value


215 Query SELECT @ @global. Relay_log_purge as Value


215 Query Show SLAVE STATUS


215 Query SELECT Repl_slave_priv as Value from mysql.user WHERE user = ' slave '


140928 10:17:09 216 Connect mha@192.168.153.151 on


216 Query SELECT @ @version_comment Limit 1


216 Query Set Sql_log_bin=0


216 Query CREATE table if not exists mysql.apply_diff_relay_logs_test (id int)


216 Query INSERT INTO mysql.apply_diff_relay_logs_test values (1)


216 Query Update mysql.apply_diff_relay_logs_test set id=id+1 where id=1


216 Query Delete from mysql.apply_diff_relay_logs_test


216 Query drop Table Mysql.apply_diff_relay_logs_test


140928 10:17:10 216 Quit


140928 10:17:11 215 Quit


140928 10:17:50 217 Connect mha@192.168.153.150 on


217 Query Set Autocommit=1


217 Query SELECT connection_id () as Value


218 Connect mha@192.168.153.150 on


218 Query Set Autocommit=1


218 Query SELECT connection_id () as Value


218 Query SET wait_timeout=86400


218 Query SELECT @ @global. server_id as Value


218 Query SELECT VERSION () as Value


218 Query show GLOBAL VARIABLES like ' Log_bin '


218 Query Show MASTER STATUS


218 Query SELECT @ @global. relay_log_info_repository as Value


218 Query SELECT @ @global. DataDir as Value


218 Query SELECT @ @global. Relay_log_info_file as Value


218 Query SELECT @ @global. DataDir as Value


218 Query Show SLAVE STATUS


218 Query SELECT @ @global. read_only as Value


218 Query SELECT @ @global. Relay_log_purge as Value


218 Query Show SLAVE STATUS


219 Connect mha@192.168.153.150 on


219 Query Set Autocommit=1


219 Query SELECT connection_id () as Value


mha@192.168.153.150 Connect


Autocommit=1 Query Set


Query SELECT connection_id () as Value


wait_timeout=86400 Query SET


The Query SELECT @ @global. server_id as Value


Query SELECT VERSION () as Value


VARIABLES Query Show GLOBAL-like ' Log_bin '


Query Show MASTER STATUS


The Query SELECT @ @global. relay_log_info_repository as Value


The Query SELECT @ @global. DataDir as Value


The Query SELECT @ @global. Relay_log_info_file as Value


The Query SELECT @ @global. DataDir as Value


Query Show SLAVE STATUS


The Query SELECT @ @global. read_only as Value


The Query SELECT @ @global. Relay_log_purge as Value


Query Show SLAVE STATUS


Query SELECT get_lock (' Mha_master_high_availability_failover ', ' 1 ') as Value


Query Show SLAVE STATUS


Io_thread Query STOP SLAVE


Query Show SLAVE STATUS


140928 10:17:51 Query Show SLAVE STATUS


Query Show SLAVE STATUS


Sql_thread Query STOP SLAVE


Query Show SLAVE STATUS


Query Show MASTER STATUS


The Query SELECT @ @global. read_only as Value


221 Connect slave@192.168.153.152 on


221 Query SELECT Unix_timestamp ()


221 Query show VARIABLES like ' server_id '


221 Query SET @master_heartbeat_period = 1799999979520


221 Query SET @master_binlog_checksum = @ @global. binlog_checksum


221 Query SELECT @master_binlog_checksum


221 Query SELECT @ @GLOBAL. Gtid_mode


221 Query show VARIABLES like ' Server_uuid '


221 Query SET @slave_uuid = ' dda2f003-4244-11e4-b851-000c29da163f '


221 Binlog Dump Log: ' mysql-bin.000016 ' pos:688


SLAVE Query STOP


Query Show SLAVE STATUS


Query RESET SLAVE/*!50516 All * *


Query Show SLAVE STATUS


Release_lock Query SELECT (' Mha_master_high_availability_failover ') as Value


Quit


DB3:

[Root@localhost ~]# Cat/var/lib/mysql/localhost.log


140928 10:17:04 223 Connect mha@192.168.153.150 on


223 Query Set Autocommit=1


223 Query SELECT connection_id () as Value


224 Connect mha@192.168.153.150 on


224 Query Set Autocommit=1


224 Query SELECT connection_id () as Value


224 Query SET wait_timeout=86400


224 Query SELECT @ @global. server_id as Value


224 Query SELECT VERSION () as Value


224 Query show GLOBAL VARIABLES like ' Log_bin '


224 Query Show MASTER STATUS


224 Query SELECT @ @global. relay_log_info_repository as Value


224 Query SELECT @ @global. DataDir as Value


224 Query SELECT @ @global. Relay_log_info_file as Value


224 Query SELECT @ @global. DataDir as Value


224 Query Show SLAVE STATUS


224 Query SELECT @ @global. read_only as Value


224 Query SELECT @ @global. Relay_log_purge as Value


224 Query Show SLAVE STATUS


140928 10:17:10 Connect mha@192.168.153.152 on


Query SELECT @ @version_comment Limit 1


Query Set Sql_log_bin=0


Query CREATE table if not exists mysql.apply_diff_relay_logs_test (id int)


Query INSERT INTO mysql.apply_diff_relay_logs_test values (1)


Query Update mysql.apply_diff_relay_logs_test set id=id+1 where id=1


Query Delete from Mysql.apply_diff_relay_logs_test


Query drop table Mysql.apply_diff_relay_logs_test


140928 10:17:11 Quit


224 Quit


#开始failover流程的监测


140928 10:17:50 mha@192.168.153.150 on


Autocommit=1 Query Set


connection_id Query SELECT () as Value


mha@192.168.153.150 Connect on


Autocommit=1 Query Set


connection_id Query SELECT () as Value


wait_timeout=86400 Query SET


The Query SELECT @ @global. server_id as Value


The Query SELECT VERSION () as Value


The show GLOBAL VARIABLES like ' Log_bin '


Show MASTER STATUS in Query


The Query SELECT @ @global. relay_log_info_repository as Value


The Query SELECT @ @global. DataDir as Value


The Query SELECT @ @global. Relay_log_info_file as Value


The Query SELECT @ @global. DataDir as Value


Show SLAVE STATUS


The Query SELECT @ @global. read_only as Value


The Query SELECT @ @global. Relay_log_purge as Value


Show SLAVE STATUS


#正式开始failover的监测


228 Connect mha@192.168.153.150 on


228 Query Set Autocommit=1


228 Query SELECT connection_id () as Value


229 Connect mha@192.168.153.150 on


229 Query Set Autocommit=1


229 Query SELECT connection_id () as Value


229 Query SET wait_timeout=86400


229 Query SELECT @ @global. server_id as Value


229 Query SELECT VERSION () as Value


229 Query Show GLOBAL VARIABLES like ' Log_bin '


229 Query Show MASTER STATUS


229 Query SELECT @ @global. relay_log_info_repository as Value


229 Query SELECT @ @global. DataDir as Value


229 Query SELECT @ @global. Relay_log_info_file as Value


229 Query SELECT @ @global. DataDir as Value


229 Query Show SLAVE STATUS


229 Query SELECT @ @global. read_only as Value


229 Query SELECT @ @global. Relay_log_purge as Value


229 Query Show SLAVE STATUS


229 Query SELECT Get_lock (' Mha_master_high_availability_failover ', ' 1 ') as Value


229 Query Show SLAVE STATUS


229 Query STOP SLAVE io_thread


229 Query Show SLAVE STATUS


140928 10:17:51 229 Query Show SLAVE STATUS


229 Query Show SLAVE STATUS


229 Query Show SLAVE STATUS


229 Query Show SLAVE STATUS


229 Query STOP SLAVE sql_thread


229 Query Show SLAVE STATUS


229 Query STOP SLAVE


229 Query Show SLAVE STATUS


229 Query RESET SLAVE


229 Query Change MASTER to Master_host = ' 192.168.153.151 ' master_user = ' slave ' Master_password = Master_port = 3306 Master_log_file = ' mysql-bin.000016 ' Master_log_pos = 688


229 Query START SLAVE


230 Connect out slave@192.168.153.151:3306


229 Query Show SLAVE STATUS


229 Query SELECT Release_lock (' Mha_master_high_availability_failover ') as Value


229 Quit


140928 10:18:07 236 Connect root@localhost on


236 Query SELECT @ @version_comment Limit 1


236 Query Select USER ()


140928 10:18:10 236 Quit


MHA Manage.log:

[Root@localhost ~]# Cat/var/log/masterha/app1/manager.log
#启动前的准备工作

#检查服务器状态, get related parameter settings


Sun SEP 10:17:03 2014-[INFO] mha::mastermonitor version 0.55.


Sun SEP 10:17:04 2014-[info] Dead Servers:


Sun SEP 10:17:04 2014-[info] Alive Servers:


Sun SEP 10:17:04 2014-[info] 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:04 2014-[info] 192.168.153.151 (192.168.153.151:3306)


Sun SEP 10:17:04 2014-[info] 192.168.153.152 (192.168.153.152:3306)


Sun SEP 10:17:04 2014-[info] Alive Slaves:


Sun SEP 10:17:04 2014-[info] 192.168.153.151 (192.168.153.151:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:04 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:04 2014-[INFO] Primary candidate for the new Master (Candidate_master is set)


Sun SEP 10:17:04 2014-[info] 192.168.153.152 (192.168.153.152:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:04 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:04 2014-[info] not candidate to the new Master (No_master is set)


Sun SEP 10:17:04 2014-[INFO] current Alive master:192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:04 2014-[info] Checking slave configurations.


Sun SEP 10:17:04 2014-[info] Read_only=1 is isn't set on slave 192.168.153.151 (192.168.153.151:3306).


Sun SEP 10:17:04 2014-[warning] relay_log_purge=0 is isn't set on slave 192.168.153.151 (192.168.153.151:3306).


Sun SEP 10:17:04 2014-[info] Read_only=1 is isn't set on slave 192.168.153.152 (192.168.153.152:3306).


Sun SEP 10:17:04 2014-[warning] relay_log_purge=0 is isn't set on slave 192.168.153.152 (192.168.153.152:3306).


Sun SEP 10:17:04 2014-[INFO] Checking replication filtering settings.


Sun SEP 10:17:04 2014-[info] binlog_do_db=, binlog_ignore_db=


Sun SEP 10:17:04 2014-[info] Replication filtering check OK.


#测试ssh连接是否成功


Sun SEP 10:17:04 2014-[INFO] Starting SSH connection tests.


Sun SEP 10:17:07 2014-[INFO] All SSH connection tests passed successfully.


#测试MHA node is available


Sun SEP 10:17:07 2014-[info] Checking MHA Node version.


Sun SEP 10:17:08 2014-[info] Version check OK.


Sun SEP 10:17:08 2014-[info] Checking SSH publickey authentication settings on the current master.


Sun SEP 10:17:08 2014-[info] healthcheck:ssh to 192.168.153.150 is reachable.


Sun SEP 10:17:09 2014-[info] Master MHA Node version is 0.54.


Sun SEP 10:17:09 2014-[INFO] Checking Recovery script configurations on the current master.


Sun SEP 10:17:09 2014-[info] executing command:save_binary_logs--command=test--start_pos=4--binlog_dir=/var/lib /mysql,/var/log/mysql--output_file=/var/log/masterha/app1/save_binary_logs_test--manager_version=0.55--start_ file=mysql-bin.000026


#创建MHA日志目录


Sun SEP 10:17:09 2014-[info] connecting to root@192.168.153.150 (192.168.153.150).


Creating/var/log/masterha/app1 if not exists. Ok.


Checking output directory is accessible or not.


Ok.


Binlog found At/var/lib/mysql, up to mysql-bin.000026


Sun SEP 10:17:09 2014-[info] Master setting check done.


#master的检查到此完毕

#开始检查slave的差异日志应用权限


Sun SEP 10:17:09 2014-[info] Checking SSH publickey authentication and Checking recovery script configurations on all Alive slave servers.


Sun SEP 10:17:09 2014-[info] executing command:apply_diff_relay_logs--command=test--slave_user= ' MHA '--slave_ho st=192.168.153.151--slave_ip=192.168.153.151--slave_port=3306--workdir=/var/log/masterha/app1--target_version=  5.6.20-68.0-log--manager_version=0.55--relay_log_info=/var/lib/mysql/relay-log.info--relay_dir=/var/lib/mysql/ --slave_pass=xxx


Sun SEP 10:17:09 2014-[info] connecting to root@192.168.153.151 (192.168.153.151:22).


Checking Slave recovery Environment settings.


Opening/var/lib/mysql/relay-log.info ... ok.


Relay Log found At/var/lib/mysql, up to mysql-relay.000003


Temporary relay log file is/var/lib/mysql/mysql-relay.000003


Testing MySQL connection and privileges. Warning:using a password on the command line interface can is insecure.


Done.


Testing Mysqlbinlog output. Done.


Cleaning up test file (s). Done.


Sun SEP 10:17:10 2014-[info] executing command:apply_diff_relay_logs--command=test--slave_user= ' MHA '--slave_ho st=192.168.153.152--slave_ip=192.168.153.152--slave_port=3306--workdir=/var/log/masterha/app1--target_version=  5.6.20-68.0-log--manager_version=0.55--relay_log_info=/var/lib/mysql/relay-log.info--relay_dir=/var/lib/mysql/ --slave_pass=xxx


Sun SEP 10:17:10 2014-[info] connecting to root@192.168.153.152 (192.168.153.152:22).


Checking Slave recovery Environment settings.


Opening/var/lib/mysql/relay-log.info ... ok.


Relay Log found At/var/lib/mysql, up to mysql-relay.000003


Temporary relay log file is/var/lib/mysql/mysql-relay.000003


Testing MySQL connection and privileges. Warning:using a password on the command line interface can is insecure.


Done.


Testing Mysqlbinlog output. Done.


Cleaning up test file (s). Done.


Sun SEP 10:17:11 2014-[INFO] slaves settings check done.


Sun SEP 10:17:11 2014-[INFO]


192.168.153.150 (Current master)


+--192.168.153.151


+--192.168.153.152

#调试master_ip_failover_script
Sun SEP 10:17:11 2014-[warning] master_ip_failover_script is not defined.
#调试shutdown_script
Sun SEP 10:17:11 2014-[INFO] Checking shutdown script Status:
Sun SEP 10:17:11 2014-[info]/opt/master_ip_failover.sh--command=status--ssh_user=root-I. p=192.168.153.150
Sun SEP 10:17:11 2014-[info] OK.
Sun SEP 10:17:11 2014-[info] Set Master ping interval 3 seconds.
#设置二次检查的主机
Sun SEP 10:17:11 2014-[info] Set secondary check script:masterha_secondary_check-s 192.168.153.151-s 192.168.153.1 52
Sun SEP 10:17:11 2014-[info] Starting ping Health check on 192.168.153.150 (192.168.153.150:3306).

#MHA启动完毕, into the monitoring state
Sun SEP 10:17:11 2014-[info] Ping (SELECT) succeeded, waiting until MySQL doesn ' t respond.

#监测DB1服务器挂了
Sun SEP 10:17:41 2014-[warning] Got error on MySQL select ping:2006 (MySQL server has gone)

#通过定义的二次监测, make sure Master is dead.
Sun SEP 10:17:41 2014-[INFO] executing seconary network check script:masterha_secondary_check-s 192.168.153.151-s 192.168.153.152--user=root--master_host=192.168.153.150--master_ip=192.168.153.150--master_port=3306
Sun SEP 10:17:41 2014-[info] executing SSH check script:save_binary_logs--command=test--start_pos=4--binlog_dir=/ Var/lib/mysql,/var/log/mysql--output_file=/var/log/masterha/app1/save_binary_logs_test--manager_version=0.55-- Binlog_prefix=mysql-bin
Monitoring server 192.168.153.151 is reachable, Master isn't reachable from 192.168.153.151. Ok.
Sun SEP 10:17:42 2014-[info] healthcheck:ssh to 192.168.153.150 is reachable.
Monitoring server 192.168.153.152 is reachable, Master isn't reachable from 192.168.153.152. Ok.

#确认master挂了, start into the failover process


#再试尝试连接master和master的ssh


Sun SEP 10:17:42 2014-[info] Master isn't reachable from all other monitoring servers. Failover should start.


Sun SEP 10:17:44 2014-[warning] Got error on MySQL connect:2013 (Lost connection to MySQL server at ' reading initial Communication packet ', System error:111)


Sun SEP 10:17:44 2014-[WARNING] Connection failed 1 time (s).


Sun SEP 10:17:47 2014-[warning] Got error on MySQL connect:2013 (Lost connection to MySQL server at ' reading initial Communication packet ', System error:111)


Sun SEP 10:17:47 2014-[warning] Connection failed 2 time (s).


Sun SEP 10:17:50 2014-[warning] Got error on MySQL connect:2013 (Lost connection to MySQL server at ' reading initial Communication packet ', System error:111)


Sun SEP 10:17:50 2014-[warning] Connection failed 3 time (s).


Sun SEP 10:17:50 2014-[warning] Master is not reachable from health checker!


Sun SEP 10:17:50 2014-[warning] Master 192.168.153.150 (192.168.153.150:3306) is not reachable!


Sun SEP 10:17:50 2014-[warning] SSH is reachable.


#通过配置文件, monitoring the status of other slave


Sun SEP 10:17:50 2014-[info] connecting to a master server failed. Reading configuration file/etc/masterha_default.cnf and/etc/app1.cnf again, and trying to connect to all servers to CHEC K Server Status.


Sun SEP 10:17:50 2014-[warning] Global configuration file/etc/masterha_default.cnf not found. Skipping.


Sun SEP 10:17:50 2014-[INFO] Reading application default configurations from/etc/app1.cnf.


Sun SEP 10:17:50 2014-[INFO] Reading server configurations from/etc/app1.cnf.


Sun SEP 10:17:50 2014-[info] Dead Servers:


Sun SEP 10:17:50 2014-[info] 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:50 2014-[info] Alive Servers:


Sun SEP 10:17:50 2014-[info] 192.168.153.151 (192.168.153.151:3306)


Sun SEP 10:17:50 2014-[info] 192.168.153.152 (192.168.153.152:3306)


Sun SEP 10:17:50 2014-[info] Alive Slaves:


Sun SEP 10:17:50 2014-[info] 192.168.153.151 (192.168.153.151:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:50 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:50 2014-[INFO] Primary candidate for the new Master (Candidate_master is set)


Sun SEP 10:17:50 2014-[info] 192.168.153.152 (192.168.153.152:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:50 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:50 2014-[info] not candidate to the new Master (No_master is set)


#再次监测slave的配置是否有变化, compliance with failover conditions


Sun SEP 10:17:50 2014-[info] Checking slave configurations.


Sun SEP 10:17:50 2014-[info] Read_only=1 is isn't set on slave 192.168.153.151 (192.168.153.151:3306).


Sun SEP 10:17:50 2014-[warning] relay_log_purge=0 is isn't set on slave 192.168.153.151 (192.168.153.151:3306).


Sun SEP 10:17:50 2014-[info] Read_only=1 is isn't set on slave 192.168.153.152 (192.168.153.152:3306).


Sun SEP 10:17:50 2014-[warning] relay_log_purge=0 is isn't set on slave 192.168.153.152 (192.168.153.152:3306).


Sun SEP 10:17:50 2014-[INFO] Checking replication filtering settings.


Sun SEP 10:17:50 2014-[info] Replication filtering check OK.


Sun SEP 10:17:50 2014-[info] Master is down!


Sun SEP 10:17:50 2014-[INFO] terminating monitoring script.


Sun SEP 10:17:50 2014-[INFO] Got exit code (Master dead).


Sun SEP 10:17:50 2014-[INFO] mha::masterfailover version 0.55.


#正式开始failover


Sun SEP 10:17:50 2014-[info] starting master failover.


Sun SEP 10:17:50 2014-[INFO]

#再次对slave配置做检查


Sun SEP 10:17:50 2014-[INFO] * Phase 1:configuration Check Phase.


Sun SEP 10:17:50 2014-[INFO]


Sun SEP 10:17:50 2014-[info] Dead Servers:


Sun SEP 10:17:50 2014-[info] 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:50 2014-[info] Checking master reachability via MySQL (double check).


Sun SEP 10:17:50 2014-[info] OK.


Sun SEP 10:17:50 2014-[info] Alive Servers:


Sun SEP 10:17:50 2014-[info] 192.168.153.151 (192.168.153.151:3306)


Sun SEP 10:17:50 2014-[info] 192.168.153.152 (192.168.153.152:3306)


Sun SEP 10:17:50 2014-[info] Alive Slaves:


Sun SEP 10:17:50 2014-[info] 192.168.153.151 (192.168.153.151:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:50 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:50 2014-[INFO] Primary candidate for the new Master (Candidate_master is set)


Sun SEP 10:17:50 2014-[info] 192.168.153.152 (192.168.153.152:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:50 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:50 2014-[info] not candidate to the new Master (No_master is set)


Sun SEP 10:17:50 2014-[INFO] * * Phase 1:configuration Check Phase completed.


Sun SEP 10:17:50 2014-[INFO]

#对原Master做master_ip_failover_script和shutdown_script的操作
Sun SEP 10:17:50 2014-[INFO] * Phase 2:dead Master Shutdown Phase.
Sun SEP 10:17:50 2014-[INFO]
Sun SEP 10:17:50 2014-[info] Forcing shutdown so this applications connect to the current master.
Sun SEP 10:17:50 2014-[warning] master_ip_failover_script is not set. Skipping invalidating dead master IP address.
Sun SEP 10:17:50 2014-[INFO] executing SHUTDOWN script:
Sun SEP 10:17:50 2014-[info]/opt/master_ip_failover.sh--command=stopssh--ssh_user=root--host=192.168.153.150 --ip=192.168.153.150--port=3306
Sun SEP 10:17:51 2014-[info] power was done.

Sun SEP 10:17:51 2014-[INFO] * Phase 2:dead Master Shutdown Phase.
Sun SEP 10:17:51 2014-[INFO]

#开始差异日志的恢复: Get the binlog position slave last


Sun SEP 10:17:51 2014-[INFO] * Phase 3:master Recovery Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] * Phase 3.1:getting Latest slaves Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[info] The latest binary log file/position on all slaves is mysql-bin.000026:120


Sun SEP 10:17:51 2014-[info] Latest slaves (slaves that received relay log files to the Latest):


Sun SEP 10:17:51 2014-[info] 192.168.153.151 (192.168.153.151:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:51 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:51 2014-[INFO] Primary candidate for the new Master (Candidate_master is set)


Sun SEP 10:17:51 2014-[info] 192.168.153.152 (192.168.153.152:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:51 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:51 2014-[info] not candidate to the new Master (No_master is set)


Sun SEP 10:17:51 2014-[INFO] The oldest binary log file/position on all slaves is mysql-bin.000026:120


Sun SEP 10:17:51 2014-[info] Oldest slaves:


Sun SEP 10:17:51 2014-[info] 192.168.153.151 (192.168.153.151:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:51 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:51 2014-[INFO] Primary candidate for the new Master (Candidate_master is set)


Sun SEP 10:17:51 2014-[info] 192.168.153.152 (192.168.153.152:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:51 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:51 2014-[info] not candidate to the new Master (No_master is set)


Sun SEP 10:17:51 2014-[INFO]


#获取原master的binlog日志


Sun SEP 10:17:51 2014-[INFO] * Phase 3.2:saving Dead Master ' s Binlog Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[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 Los T.


Sun SEP 10:17:51 2014-[INFO]

#确定新的master


Sun SEP 10:17:51 2014-[INFO] * Phase 3.3:determining New Master Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[info] Finding the latest slave that has all relay logs for recovering to other slaves.


Sun SEP 10:17:51 2014-[info] All slaves received relay logs to the same. No need to resync each other.


Sun SEP 10:17:51 2014-[INFO] searching new master from slaves.


Sun SEP 10:17:51 2014-[INFO] candidate Masters from the configuration file:


Sun SEP 10:17:51 2014-[info] 192.168.153.151 (192.168.153.151:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:51 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:51 2014-[INFO] Primary candidate for the new Master (Candidate_master is set)


Sun SEP 10:17:51 2014-[info] non-candidate Masters:


Sun SEP 10:17:51 2014-[info] 192.168.153.152 (192.168.153.152:3306) version=5.6.20-68.0-log (oldest major Version b Etween slaves) log-bin:enabled


Sun SEP 10:17:51 2014-[info] replicating from 192.168.153.150 (192.168.153.150:3306)


Sun SEP 10:17:51 2014-[info] not candidate to the new Master (No_master is set)


Sun SEP 10:17:51 2014-[info] searching from candidate_master slaves which have received the latest relay log events. .


Sun SEP 10:17:51 2014-[info] New Master is 192.168.153.151 (192.168.153.151:3306)


Sun SEP 10:17:51 2014-[info] starting master failover.


Sun SEP 10:17:51 2014-[INFO]


From:


192.168.153.150 (Current master)


+--192.168.153.151


+--192.168.153.152

To:


192.168.153.151 (new Master)


+--192.168.153.152


Sun SEP 10:17:51 2014-[INFO]


#在new Binlog Log with differences applied on Master


Sun SEP 10:17:51 2014-[INFO] * Phase 3.3:new Master Diff Log Generation Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] This server has all relay logs. No need to generate diff files from the latest slave.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] * Phase 3.4:master Log Apply Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] *notice:if Any error happens from this phase, manual recovery is needed.


Sun SEP 10:17:51 2014-[INFO] starting recovery on 192.168.153.151 (192.168.153.151:3306).


Sun SEP 10:17:51 2014-[INFO] This server has all relay logs. Waiting all logs to be applied.


Sun SEP 10:17:51 2014-[info] done.


Sun SEP 10:17:51 2014-[info] All relay logs were successfully.


#获取new Master's binlog location.


Sun SEP 10:17:51 2014-[info] getting new master ' s binlog name and position.


Sun SEP 10:17:51 2014-[INFO] mysql-bin.000016:688


Sun SEP 10:17:51 2014-[info] All other slaves should start replication from here. Statement should be:change MASTER to master_host= ' 192.168.153.151 ', master_port=3306, master_log_file= ' Mysql-bin.000016 ', master_log_pos=688, master_user= ' slave ', master_password= ' xxx ';


#如果有master_ip_failover_script, then set the VIP for new master


Sun SEP 10:17:51 2014-[warning] master_ip_failover_script is not set. Skipping taking over the new master IP address.


Sun SEP 10:17:51 2014-[INFO] * * Finished master recovery successfully.


Sun SEP 10:17:51 2014-[INFO] * Phase 3:master Recovery Phase.


Sun SEP 10:17:51 2014-[INFO]

#开始恢复其他slave, but also from the original master Binlog contrast to do the recovery


Sun SEP 10:17:51 2014-[INFO] * Phase 4:slaves Recovery Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] * Phase 4.1:starting Parallel Slave Diff Log Generation Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO]--Slave diff file generation on host 192.168.153.152 (192.168.153.152:3306) started, PID : 8387. Check tmp Log/var/log/masterha/app1/192.168.153.152_3306_20140928101750.log If it takes time.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] Log messages from 192.168.153.152 ...


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] This server has all relay logs. No need to generate diff files from the latest slave.


Sun SEP 10:17:51 2014-[info] End of log messages from 192.168.153.152.


Sun SEP 10:17:51 2014-[INFO]--192.168.153.152 (192.168.153.152:3306) has the latest relay log events.


Sun SEP 10:17:51 2014-[INFO] generating relay diff files from the latest slave.


Sun SEP 10:17:51 2014-[INFO]

Sun SEP 10:17:51 2014-[INFO] * Phase 4.2:starting Parallel Slave Log Apply Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO]--Slave recovery on host 192.168.153.152 (192.168.153.152:3306) started, pid:8389. Check tmp Log/var/log/masterha/app1/192.168.153.152_3306_20140928101750.log If it takes time.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] Log messages from 192.168.153.152 ...


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] starting recovery on 192.168.153.152 (192.168.153.152:3306).


Sun SEP 10:17:51 2014-[INFO] This server has all relay logs. Waiting all logs to be applied.


Sun SEP 10:17:51 2014-[info] done.


Sun SEP 10:17:51 2014-[info] All relay logs were successfully.


#差异日志应用完成以后, toggle all slave to new master.


Sun SEP 10:17:51 2014-[info] resetting slave 192.168.153.152 (192.168.153.152:3306) and starting replication from the New Master 192.168.153.151 (192.168.153.151:3306).


Sun SEP 10:17:51 2014-[info] executed change MASTER.


Sun SEP 10:17:51 2014-[info] Slave started.


Sun SEP 10:17:51 2014-[info] End of log messages from 192.168.153.152.


Sun SEP 10:17:51 2014-[INFO]--Slave recovery on host 192.168.153.152 (192.168.153.152:3306) succeeded.


Sun SEP 10:17:51 2014-[info] All new slave servers recovered successfully.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] * Phase 5:new master cleanup Phase.


Sun SEP 10:17:51 2014-[INFO]


Sun SEP 10:17:51 2014-[INFO] resetting slave info on the new master.


Sun SEP 10:17:51 2014-[INFO] 192.168.153.151:resetting slave info succeeded.


Sun SEP 10:17:51 2014-[info] Master failover to 192.168.153.151 (192.168.153.151:3306) completed successfully.


Sun SEP 10:17:51 2014-[INFO]

#failover操作完成, generate failover reports
-----Failover-----

App1:mysql Master failover 192.168.153.150 to 192.168.153.151 succeeded

Master 192.168.153.150 is down!

Check MHA Manager logs at Localhost.localdomain:/var/log/masterha/app1/manager.log for details.

Started automated (non-interactive) failover.
Power off 192.168.153.150.
The latest slave 192.168.153.151 (192.168.153.151:3306) has all relay to logs for recovery.
Selected 192.168.153.151 as a new master.
192.168.153.151:ok:applying all logs succeeded.
192.168.153.152:this host has the latest relay log events.
Generating relay diff files from the latest slave succeeded.
192.168.153.152:ok:applying all logs succeeded. Slave started, replicating from 192.168.153.151.
192.168.153.151:resetting Slave info succeeded.
Master failover to 192.168.153.151 (192.168.153.151:3306) completed