MysqlMaster切换日志分析示例

下面是MHA从启动,到failover的完整manager.log,以及集群中所有mysql的general.log.我们可以通过这些日志,更多的了解和分析MHA的运行原理.对用好MHA有很多帮助。
架构如下:
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', '12') 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
220 Connect mha@192.168.153.150 on
220 Query set autocommit=1
220 Query SELECT CONNECTION_ID() AS Value
220 Query SET wait_timeout=86400
220 Query SELECT @@global.server_id As Value
220 Query SELECT VERSION() AS Value
220 Query SHOW GLOBAL VARIABLES LIKE 'log_bin'
220 Query SHOW MASTER STATUS
220 Query SELECT @@global.relay_log_info_repository AS Value
220 Query SELECT @@global.datadir AS Value
220 Query SELECT @@global.relay_log_info_file AS Value
220 Query SELECT @@global.datadir AS Value
220 Query SHOW SLAVE STATUS
220 Query SELECT @@global.read_only As Value
220 Query SELECT @@global.relay_log_purge As Value
220 Query SHOW SLAVE STATUS
220 Query SELECT GET_LOCK('MHA_Master_High_Availability_Failover', '1') AS Value
220 Query SHOW SLAVE STATUS
220 Query STOP SLAVE IO_THREAD
220 Query SHOW SLAVE STATUS
140928 10:17:51 220 Query SHOW SLAVE STATUS
220 Query SHOW SLAVE STATUS
220 Query STOP SLAVE SQL_THREAD
220 Query SHOW SLAVE STATUS
220 Query SHOW MASTER STATUS
220 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
220 Query STOP SLAVE
220 Query SHOW SLAVE STATUS
220 Query RESET SLAVE /*!50516 ALL */
220 Query SHOW SLAVE STATUS
220 Query SELECT RELEASE_LOCK('MHA_Master_High_Availability_Failover') As Value
220 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 225 Connect mha@192.168.153.152 on
225 Query select @@version_comment limit 1
225 Query set sql_log_bin=0
225 Query create table if not exists mysql.apply_diff_relay_logs_test(id int)
225 Query insert into mysql.apply_diff_relay_logs_test values(1)
225 Query update mysql.apply_diff_relay_logs_test set id=id+1 where id=1
225 Query delete from mysql.apply_diff_relay_logs_test
225 Query drop table mysql.apply_diff_relay_logs_test
140928 10:17:11 225 Quit
224 Quit
#开始failover流程的监测
140928 10:17:50 226 Connect mha@192.168.153.150 on
226 Query set autocommit=1
226 Query SELECT CONNECTION_ID() AS Value
227 Connect mha@192.168.153.150 on
227 Query set autocommit=1
227 Query SELECT CONNECTION_ID() AS Value
227 Query SET wait_timeout=86400
227 Query SELECT @@global.server_id As Value
227 Query SELECT VERSION() AS Value
227 Query SHOW GLOBAL VARIABLES LIKE 'log_bin'
227 Query SHOW MASTER STATUS
227 Query SELECT @@global.relay_log_info_repository AS Value
227 Query SELECT @@global.datadir AS Value
227 Query SELECT @@global.relay_log_info_file AS Value
227 Query SELECT @@global.datadir AS Value
227 Query SHOW SLAVE STATUS
227 Query SELECT @@global.read_only As Value
227 Query SELECT @@global.relay_log_purge As Value
227 Query 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
#启动前的准备工作

#检查服务器状态,获取相关参数设置
Sun Sep 28 10:17:03 2014 - [info] MHA::MasterMonitor version 0.55.
Sun Sep 28 10:17:04 2014 - [info] Dead Servers:
Sun Sep 28 10:17:04 2014 - [info] Alive Servers:
Sun Sep 28 10:17:04 2014 - [info] 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:04 2014 - [info] 192.168.153.151(192.168.153.151:3306)
Sun Sep 28 10:17:04 2014 - [info] 192.168.153.152(192.168.153.152:3306)
Sun Sep 28 10:17:04 2014 - [info] Alive Slaves:
Sun Sep 28 10:17:04 2014 - [info] 192.168.153.151(192.168.153.151:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:04 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:04 2014 - [info] Primary candidate for the new Master (candidate_master is set)
Sun Sep 28 10:17:04 2014 - [info] 192.168.153.152(192.168.153.152:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:04 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:04 2014 - [info] Not candidate for the new Master (no_master is set)
Sun Sep 28 10:17:04 2014 - [info] Current Alive Master: 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:04 2014 - [info] Checking slave configurations..
Sun Sep 28 10:17:04 2014 - [info] read_only=1 is not set on slave 192.168.153.151(192.168.153.151:3306).
Sun Sep 28 10:17:04 2014 - [warning] relay_log_purge=0 is not set on slave 192.168.153.151(192.168.153.151:3306).
Sun Sep 28 10:17:04 2014 - [info] read_only=1 is not set on slave 192.168.153.152(192.168.153.152:3306).
Sun Sep 28 10:17:04 2014 - [warning] relay_log_purge=0 is not set on slave 192.168.153.152(192.168.153.152:3306).
Sun Sep 28 10:17:04 2014 - [info] Checking replication filtering settings..
Sun Sep 28 10:17:04 2014 - [info] binlog_do_db= , binlog_ignore_db=
Sun Sep 28 10:17:04 2014 - [info] Replication filtering check ok.
#测试ssh连接是否成功
Sun Sep 28 10:17:04 2014 - [info] Starting SSH connection tests..
Sun Sep 28 10:17:07 2014 - [info] All SSH connection tests passed successfully.
#测试MHA node是否可用
Sun Sep 28 10:17:07 2014 - [info] Checking MHA Node version..
Sun Sep 28 10:17:08 2014 - [info] Version check ok.
Sun Sep 28 10:17:08 2014 - [info] Checking SSH publickey authentication settings on the current master..
Sun Sep 28 10:17:08 2014 - [info] HealthCheck: SSH to 192.168.153.150 is reachable.
Sun Sep 28 10:17:09 2014 - [info] Master MHA Node version is 0.54.
Sun Sep 28 10:17:09 2014 - [info] Checking recovery script configurations on the current master..
Sun Sep 28 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 28 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 28 10:17:09 2014 - [info] Master setting check done.
#master的检查到此完毕

#开始检查slave的差异日志应用权限
Sun Sep 28 10:17:09 2014 - [info] Checking SSH publickey authentication and checking recovery script configurations on all alive slave servers..
Sun Sep 28 10:17:09 2014 - [info] Executing command : apply_diff_relay_logs --command=test --slave_user='mha' --slave_host=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 28 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 be insecure.
done.
Testing mysqlbinlog output.. done.
Cleaning up test file(s).. done.
Sun Sep 28 10:17:10 2014 - [info] Executing command : apply_diff_relay_logs --command=test --slave_user='mha' --slave_host=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 28 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 be insecure.
done.
Testing mysqlbinlog output.. done.
Cleaning up test file(s).. done.
Sun Sep 28 10:17:11 2014 - [info] Slaves settings check done.
Sun Sep 28 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 28 10:17:11 2014 - [warning] master_ip_failover_script is not defined.
#调试shutdown_script
Sun Sep 28 10:17:11 2014 - [info] Checking shutdown script status:
Sun Sep 28 10:17:11 2014 - [info] /opt/master_ip_failover.sh --command=status --ssh_user=root --host=192.168.153.150 --ip=192.168.153.150
Sun Sep 28 10:17:11 2014 - [info] OK.
Sun Sep 28 10:17:11 2014 - [info] Set master ping interval 3 seconds.
#设置二次检查的主机
Sun Sep 28 10:17:11 2014 - [info] Set secondary check script: masterha_secondary_check -s 192.168.153.151 -s 192.168.153.152
Sun Sep 28 10:17:11 2014 - [info] Starting ping health check on 192.168.153.150(192.168.153.150:3306)..

#MHA启动完毕,进入监测状态
Sun Sep 28 10:17:11 2014 - [info] Ping(SELECT) succeeded, waiting until MySQL doesn't respond..

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

#通过定义的二次监测,确认master是否挂了
Sun Sep 28 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 28 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 is not reachable from 192.168.153.151. OK.
Sun Sep 28 10:17:42 2014 - [info] HealthCheck: SSH to 192.168.153.150 is reachable.
Monitoring server 192.168.153.152 is reachable, Master is not reachable from 192.168.153.152. OK.

#确认master挂了,开始进入failover流程
#再试尝试连接master和master的ssh
Sun Sep 28 10:17:42 2014 - [info] Master is not reachable from all other monitoring servers. Failover should start.
Sun Sep 28 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 28 10:17:44 2014 - [warning] Connection failed 1 time(s)..
Sun Sep 28 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 28 10:17:47 2014 - [warning] Connection failed 2 time(s)..
Sun Sep 28 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 28 10:17:50 2014 - [warning] Connection failed 3 time(s)..
Sun Sep 28 10:17:50 2014 - [warning] Master is not reachable from health checker!
Sun Sep 28 10:17:50 2014 - [warning] Master 192.168.153.150(192.168.153.150:3306) is not reachable!
Sun Sep 28 10:17:50 2014 - [warning] SSH is reachable.
#通过配置文件,监测其他slave的状态
Sun Sep 28 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 check server status..
Sun Sep 28 10:17:50 2014 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Sun Sep 28 10:17:50 2014 - [info] Reading application default configurations from /etc/app1.cnf..
Sun Sep 28 10:17:50 2014 - [info] Reading server configurations from /etc/app1.cnf..
Sun Sep 28 10:17:50 2014 - [info] Dead Servers:
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:50 2014 - [info] Alive Servers:
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.151(192.168.153.151:3306)
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.152(192.168.153.152:3306)
Sun Sep 28 10:17:50 2014 - [info] Alive Slaves:
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.151(192.168.153.151:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:50 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:50 2014 - [info] Primary candidate for the new Master (candidate_master is set)
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.152(192.168.153.152:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:50 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:50 2014 - [info] Not candidate for the new Master (no_master is set)
#再次监测slave的配置是否有变化,是否符合failover条件
Sun Sep 28 10:17:50 2014 - [info] Checking slave configurations..
Sun Sep 28 10:17:50 2014 - [info] read_only=1 is not set on slave 192.168.153.151(192.168.153.151:3306).
Sun Sep 28 10:17:50 2014 - [warning] relay_log_purge=0 is not set on slave 192.168.153.151(192.168.153.151:3306).
Sun Sep 28 10:17:50 2014 - [info] read_only=1 is not set on slave 192.168.153.152(192.168.153.152:3306).
Sun Sep 28 10:17:50 2014 - [warning] relay_log_purge=0 is not set on slave 192.168.153.152(192.168.153.152:3306).
Sun Sep 28 10:17:50 2014 - [info] Checking replication filtering settings..
Sun Sep 28 10:17:50 2014 - [info] Replication filtering check ok.
Sun Sep 28 10:17:50 2014 - [info] Master is down!
Sun Sep 28 10:17:50 2014 - [info] Terminating monitoring script.
Sun Sep 28 10:17:50 2014 - [info] Got exit code 20 (Master dead).
Sun Sep 28 10:17:50 2014 - [info] MHA::MasterFailover version 0.55.
#正式开始failover
Sun Sep 28 10:17:50 2014 - [info] Starting master failover.
Sun Sep 28 10:17:50 2014 - [info]

#再次对slave配置做检查
Sun Sep 28 10:17:50 2014 - [info] * Phase 1: Configuration Check Phase..
Sun Sep 28 10:17:50 2014 - [info]
Sun Sep 28 10:17:50 2014 - [info] Dead Servers:
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:50 2014 - [info] Checking master reachability via mysql(double check)..
Sun Sep 28 10:17:50 2014 - [info] ok.
Sun Sep 28 10:17:50 2014 - [info] Alive Servers:
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.151(192.168.153.151:3306)
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.152(192.168.153.152:3306)
Sun Sep 28 10:17:50 2014 - [info] Alive Slaves:
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.151(192.168.153.151:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:50 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:50 2014 - [info] Primary candidate for the new Master (candidate_master is set)
Sun Sep 28 10:17:50 2014 - [info] 192.168.153.152(192.168.153.152:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:50 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:50 2014 - [info] Not candidate for the new Master (no_master is set)
Sun Sep 28 10:17:50 2014 - [info] ** Phase 1: Configuration Check Phase completed.
Sun Sep 28 10:17:50 2014 - [info]

#对原Master做master_ip_failover_script和shutdown_script的操作
Sun Sep 28 10:17:50 2014 - [info] * Phase 2: Dead Master Shutdown Phase..
Sun Sep 28 10:17:50 2014 - [info]
Sun Sep 28 10:17:50 2014 - [info] Forcing shutdown so that applications never connect to the current master..
Sun Sep 28 10:17:50 2014 - [warning] master_ip_failover_script is not set. Skipping invalidating dead master ip address.
Sun Sep 28 10:17:50 2014 - [info] Executing SHUTDOWN script:
Sun Sep 28 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 28 10:17:51 2014 - [info] Power off done.

Sun Sep 28 10:17:51 2014 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Sun Sep 28 10:17:51 2014 - [info]

#开始差异日志的恢复:获取slave最后得到的binlog位置
Sun Sep 28 10:17:51 2014 - [info] * Phase 3: Master Recovery Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] The latest binary log file/position on all slaves is mysql-bin.000026:120
Sun Sep 28 10:17:51 2014 - [info] Latest slaves (Slaves that received relay log files to the latest):
Sun Sep 28 10:17:51 2014 - [info] 192.168.153.151(192.168.153.151:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:51 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:51 2014 - [info] Primary candidate for the new Master (candidate_master is set)
Sun Sep 28 10:17:51 2014 - [info] 192.168.153.152(192.168.153.152:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:51 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:51 2014 - [info] Not candidate for the new Master (no_master is set)
Sun Sep 28 10:17:51 2014 - [info] The oldest binary log file/position on all slaves is mysql-bin.000026:120
Sun Sep 28 10:17:51 2014 - [info] Oldest slaves:
Sun Sep 28 10:17:51 2014 - [info] 192.168.153.151(192.168.153.151:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:51 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:51 2014 - [info] Primary candidate for the new Master (candidate_master is set)
Sun Sep 28 10:17:51 2014 - [info] 192.168.153.152(192.168.153.152:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:51 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:51 2014 - [info] Not candidate for the new Master (no_master is set)
Sun Sep 28 10:17:51 2014 - [info]
#获取原master的binlog日志
Sun Sep 28 10:17:51 2014 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 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 lost.
Sun Sep 28 10:17:51 2014 - [info]

#确定新的master
Sun Sep 28 10:17:51 2014 - [info] * Phase 3.3: Determining New Master Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Sun Sep 28 10:17:51 2014 - [info] All slaves received relay logs to the same position. No need to resync each other.
Sun Sep 28 10:17:51 2014 - [info] Searching new master from slaves..
Sun Sep 28 10:17:51 2014 - [info] Candidate masters from the configuration file:
Sun Sep 28 10:17:51 2014 - [info] 192.168.153.151(192.168.153.151:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:51 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:51 2014 - [info] Primary candidate for the new Master (candidate_master is set)
Sun Sep 28 10:17:51 2014 - [info] Non-candidate masters:
Sun Sep 28 10:17:51 2014 - [info] 192.168.153.152(192.168.153.152:3306) Version=5.6.20-68.0-log (oldest major version between slaves) log-bin:enabled
Sun Sep 28 10:17:51 2014 - [info] Replicating from 192.168.153.150(192.168.153.150:3306)
Sun Sep 28 10:17:51 2014 - [info] Not candidate for the new Master (no_master is set)
Sun Sep 28 10:17:51 2014 - [info] Searching from candidate_master slaves which have received the latest relay log events..
Sun Sep 28 10:17:51 2014 - [info] New master is 192.168.153.151(192.168.153.151:3306)
Sun Sep 28 10:17:51 2014 - [info] Starting master failover..
Sun Sep 28 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 28 10:17:51 2014 - [info]
#在new master上应用差异的binlog日志
Sun Sep 28 10:17:51 2014 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] * Phase 3.4: Master Log Apply Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Sun Sep 28 10:17:51 2014 - [info] Starting recovery on 192.168.153.151(192.168.153.151:3306)..
Sun Sep 28 10:17:51 2014 - [info] This server has all relay logs. Waiting all logs to be applied..
Sun Sep 28 10:17:51 2014 - [info] done.
Sun Sep 28 10:17:51 2014 - [info] All relay logs were successfully applied.
#获取new master的binlog位置。
Sun Sep 28 10:17:51 2014 - [info] Getting new master's binlog name and position..
Sun Sep 28 10:17:51 2014 - [info] mysql-bin.000016:688
Sun Sep 28 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,那么给new master设置VIP
Sun Sep 28 10:17:51 2014 - [warning] master_ip_failover_script is not set. Skipping taking over new master ip address.
Sun Sep 28 10:17:51 2014 - [info] ** Finished master recovery successfully.
Sun Sep 28 10:17:51 2014 - [info] * Phase 3: Master Recovery Phase completed.
Sun Sep 28 10:17:51 2014 - [info]

#开始恢复其他slave,也是从原master的binlog对比来做恢复
Sun Sep 28 10:17:51 2014 - [info] * Phase 4: Slaves Recovery Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 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 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] Log messages from 192.168.153.152 ...
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Sun Sep 28 10:17:51 2014 - [info] End of log messages from 192.168.153.152.
Sun Sep 28 10:17:51 2014 - [info] -- 192.168.153.152(192.168.153.152:3306) has the latest relay log events.
Sun Sep 28 10:17:51 2014 - [info] Generating relay diff files from the latest slave succeeded.
Sun Sep 28 10:17:51 2014 - [info]

Sun Sep 28 10:17:51 2014 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 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 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] Log messages from 192.168.153.152 ...
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] Starting recovery on 192.168.153.152(192.168.153.152:3306)..
Sun Sep 28 10:17:51 2014 - [info] This server has all relay logs. Waiting all logs to be applied..
Sun Sep 28 10:17:51 2014 - [info] done.
Sun Sep 28 10:17:51 2014 - [info] All relay logs were successfully applied.
#差异日志应用完成以后,切换所有slave到new master。
Sun Sep 28 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 28 10:17:51 2014 - [info] Executed CHANGE MASTER.
Sun Sep 28 10:17:51 2014 - [info] Slave started.
Sun Sep 28 10:17:51 2014 - [info] End of log messages from 192.168.153.152.
Sun Sep 28 10:17:51 2014 - [info] -- Slave recovery on host 192.168.153.152(192.168.153.152:3306) succeeded.
Sun Sep 28 10:17:51 2014 - [info] All new slave servers recovered successfully.
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] * Phase 5: New master cleanup phase..
Sun Sep 28 10:17:51 2014 - [info]
Sun Sep 28 10:17:51 2014 - [info] Resetting slave info on the new master..
Sun Sep 28 10:17:51 2014 - [info] 192.168.153.151: Resetting slave info succeeded.
Sun Sep 28 10:17:51 2014 - [info] Master failover to 192.168.153.151(192.168.153.151:3306) completed successfully.
Sun Sep 28 10:17:51 2014 - [info]

#failover操作完成,生成failover报告
----- Failover Report -----

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 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