Enabling the VIP - 192.168.1.13/24 on the new master - vdbsrv2
Mon Apr 20 14:30:36 2015 - [info] OK.
Mon Apr 20 14:30:36 2015 - [info] ** Finished master recovery successfully.
Mon Apr 20 14:30:36 2015 - [info] * Phase 3: Master Recovery Phase completed.
Mon Apr 20 14:30:36 2015 - [info]
Mon Apr 20 14:30:36 2015 - [info] * Phase 4: Slaves Recovery Phase..
Mon Apr 20 14:30:36 2015 - [info]
Mon Apr 20 14:30:36 2015 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Mon Apr 20 14:30:36 2015 - [info]
Mon Apr 20 14:30:36 2015 - [info] -- Slave diff file generation on host vdbsrv3(192.168.1.8:3306) started, pid: 7726.
Check tmp log /var/log/masterha/app1/vdbsrv3_3306_20150420143022.log if it takes time..
Mon Apr 20 14:30:37 2015 - [info]
Mon Apr 20 14:30:37 2015 - [info] Log messages from vdbsrv3 ...
Mon Apr 20 14:30:37 2015 - [info]
Mon Apr 20 14:30:36 2015 - [info] Server vdbsrv3 received relay logs up to: mysql-bin.000020:313962621
Mon Apr 20 14:30:36 2015 - [info] Need to get diffs from the latest slave(vdbsrv2) up to: mysql-bin.000020:315514388
(using the latest slave's relay logs) ###此时vdbsrv3需要从vdbsrv2获取差量日志
Mon Apr 20 14:30:36 2015 - [info] Connecting to the latest slave host vdbsrv2, generating diff relay log files..
Mon Apr 20 14:30:36 2015 - [info] Executing command: apply_diff_relay_logs --command=generate_and_send --scp_user=root --scp_host=192.168.1.8
--latest_mlf=mysql-bin.000020 --latest_rmlp=315514388 --target_mlf=mysql-bin.000020 --target_rmlp=313962621 --server_id=1001
--diff_file_readtolatest=/var/tmp/relay_from_read_to_latest_vdbsrv3_3306_20150420143022.binlog --workdir=/var/tmp --timestamp=20150420143022
--handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/data/mysqldata/relay-log.info --relay_dir=/data/mysqldata/
Mon Apr 20 14:30:37 2015 - [info]
Opening /data/mysqldata/relay-log.info ... ok.
Relay log found at /data/mysqldata, up to vdbsrv2-relay-bin.000003
Fast relay log position search succeeded.
Target relay log file/position found. start_file:vdbsrv2-relay-bin.000003, start_pos:6265486.
Concat binary/relay logs from vdbsrv2-relay-bin.000003 pos 6265486 to vdbsrv2-relay-bin.000003 EOF into
/var/tmp/relay_from_read_to_latest_vdbsrv3_3306_20150420143022.binlog .. ###注，此时是从vdbsrv2中继日志获取
Binlog Checksum enabled
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 283.. ok.
Dumping effective binlog data from /data/mysqldata/vdbsrv2-relay-bin.000003 position 6265486 to tail(7817253).. ok.
Binlog Checksum enabled
Binlog Checksum enabled
Concat succeeded.
Generating diff relay log succeeded. Saved at /var/tmp/relay_from_read_to_latest_vdbsrv3_3306_20150420143022.binlog .
scp vdbsrv2:/var/tmp/relay_from_read_to_latest_vdbsrv3_3306_20150420143022.binlog to root@192.168.1.8(22) succeeded.
Mon Apr 20 14:30:37 2015 - [info] Generating diff files succeeded.
Mon Apr 20 14:30:37 2015 - [info] End of log messages from vdbsrv3.
Mon Apr 20 14:30:37 2015 - [info] -- Slave diff log generation on host vdbsrv3(192.168.1.8:3306) succeeded.
Mon Apr 20 14:30:37 2015 - [info] Generating relay diff files from the latest slave succeeded.
Mon Apr 20 14:30:37 2015 - [info]
Mon Apr 20 14:30:37 2015 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Mon Apr 20 14:30:37 2015 - [info]
Mon Apr 20 14:30:37 2015 - [info] -- Slave recovery on host vdbsrv3(192.168.1.8:3306) started, pid: 7735.
Check tmp log /var/log/masterha/app1/vdbsrv3_3306_20150420143022.log if it takes time..
Mon Apr 20 14:30:43 2015 - [info]
Mon Apr 20 14:30:43 2015 - [info] Log messages from vdbsrv3 ...
Mon Apr 20 14:30:43 2015 - [info]
Mon Apr 20 14:30:37 2015 - [info] Sending binlog.. ###这部分则是在原master宕机后未发送的binlog部分
Mon Apr 20 14:30:38 2015 - [info] scp from local:/var/log/masterha/app1/saved_master_binlog_from_vdbsrv1_3306_20150420143022.binlog to
root@vdbsrv3:/var/tmp/saved_master_binlog_from_vdbsrv1_3306_20150420143022.binlog succeeded.
Mon Apr 20 14:30:38 2015 - [info] Starting recovery on vdbsrv3(192.168.1.8:3306)..
Mon Apr 20 14:30:38 2015 - [info] Generating diffs succeeded.
Mon Apr 20 14:30:38 2015 - [info] Waiting until all relay logs are applied.
Mon Apr 20 14:30:38 2015 - [info] done.
Mon Apr 20 14:30:38 2015 - [info] Getting slave status..
Mon Apr 20 14:30:38 2015 - [info] This slave(vdbsrv3)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000020:313962621).
No need to recover from Exec_Master_Log_Pos.
Mon Apr 20 14:30:38 2015 - [info] Connecting to the target slave host vdbsrv3, running recover script..
Mon Apr 20 14:30:38 2015 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='mha' --slave_host=vdbsrv3
--slave_ip=192.168.1.8 --slave_port=3306 --apply_files=/var/tmp/relay_from_read_to_latest_vdbsrv3_3306_20150420143022.binlog,
/var/tmp/saved_master_binlog_from_vdbsrv1_3306_20150420143022.binlog --workdir=/var/tmp --target_version=5.6.22-log
--timestamp=20150420143022 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx
Mon Apr 20 14:30:43 2015 - [info]
Concat all apply files to /var/tmp/total_binlog_for_vdbsrv3_3306.20150420143022.binlog ..
Copying the first binlog file /var/tmp/relay_from_read_to_latest_vdbsrv3_3306_20150420143022.binlog to
/var/tmp/total_binlog_for_vdbsrv3_3306.20150420143022.binlog.. ok.
Dumping binlog head events (rotate events), skipping format description events from
/var/tmp/saved_master_binlog_from_vdbsrv1_3306_20150420143022.binlog.. Binlog Checksum enabled
dumped up to pos 120. ok.
/var/tmp/saved_master_binlog_from_vdbsrv1_3306_20150420143022.binlog has effective binlog events from pos 120.
Dumping effective binlog data from /var/tmp/saved_master_binlog_from_vdbsrv1_3306_20150420143022.binlog position 120 to tail(143).. ok.
Concat succeeded.
All apply target binary logs are concatinated at /var/tmp/total_binlog_for_vdbsrv3_3306.20150420143022.binlog .
Applying differential binary/relay log files /var/tmp/relay_from_read_to_latest_vdbsrv3_3306_20150420143022.binlog,
/var/tmp/saved_master_binlog_from_vdbsrv1_3306_20150420143022.binlog on vdbsrv3:3306. This may take long time...
Applying log files succeeded.
Mon Apr 20 14:30:43 2015 - [info] All relay logs were successfully applied.
Mon Apr 20 14:30:43 2015 - [info] Resetting slave vdbsrv3(192.168.1.8:3306) and starting replication from the new master vdbsrv2(192.168.1.7:3306)..
Mon Apr 20 14:30:43 2015 - [info] Executed CHANGE MASTER.
Mon Apr 20 14:30:43 2015 - [info] Slave started.
Mon Apr 20 14:30:43 2015 - [info] End of log messages from vdbsrv3.
Mon Apr 20 14:30:43 2015 - [info] -- Slave recovery on host vdbsrv3(192.168.1.8:3306) succeeded.
Mon Apr 20 14:30:43 2015 - [info] All new slave servers recovered successfully.
Mon Apr 20 14:30:43 2015 - [info]
Mon Apr 20 14:30:43 2015 - [info] * Phase 5: New master cleanup phase..
Mon Apr 20 14:30:43 2015 - [info]
Mon Apr 20 14:30:43 2015 - [info] Resetting slave info on the new master..
Mon Apr 20 14:30:43 2015 - [info] vdbsrv2: Resetting slave info succeeded.
Mon Apr 20 14:30:43 2015 - [info] Master failover to vdbsrv2(192.168.1.7:3306) completed successfully.
Mon Apr 20 14:30:43 2015 - [info]
----- Failover Report -----
app1: MySQL Master failover vdbsrv1(192.168.1.6:3306) to vdbsrv2(192.168.1.7:3306) succeeded
Master vdbsrv1(192.168.1.6:3306) is down! ###整个failover总时间14:30:43-14:30:19=24s
Check MHA Manager logs at vdbsrv4:/var/log/masterha/app1/manager.log for details.