Wed Jun? 6 14:50:48 2012 - [warning] master_ip_failover_script is not defined. Wed Jun? 6 14:50:48 2012 - [warning] shutdown_script is not defined. Wed Jun? 6 14:50:48 2012 - [info] Set master ping interval 1 seconds. Wed Jun? 6 14:50:48 2012 - [warning] secondary_check_script is not defined. It is highly recommended setting it to check master reachability from two or more routes. Wed Jun? 6 14:50:48 2012 - [info] Starting ping health check on 192.168.123.13(192.168.123.13:3306).. Wed Jun? 6 14:50:48 2012 - [info] Ping succeeded, sleeping until it doesn't respond..
Wed Jun? 6 14:51:32 2012 - [warning] Got error on MySQL ping: 2006 (MySQL server has gone away) Wed Jun? 6 14:51:32 2012 - [info] HealthCheck: SSH to 192.168.123.13 is reachable. Wed Jun? 6 14:51:33 2012 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111) Wed Jun? 6 14:51:33 2012 - [warning] Connection failed 1 time(s).. Wed Jun? 6 14:51:34 2012 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111) Wed Jun? 6 14:51:34 2012 - [warning] Connection failed 2 time(s).. Wed Jun? 6 14:51:35 2012 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111) Wed Jun? 6 14:51:35 2012 - [warning] Connection failed 3 time(s).. Wed Jun? 6 14:51:35 2012 - [warning] Master is not reachable from health checker! Wed Jun? 6 14:51:35 2012 - [warning] Master 192.168.123.13(192.168.123.13:3306) is not reachable! Wed Jun? 6 14:51:35 2012 - [warning] SSH is reachable. Wed Jun? 6 14:51:35 2012 - [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.. Wed Jun? 6 14:51:35 2012 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping. Wed Jun? 6 14:51:35 2012 - [info] Reading application default configurations from /etc/masterha/app1.cnf.. Wed Jun? 6 14:51:35 2012 - [info] Reading server configurations from /etc/masterha/app1.cnf.. Wed Jun? 6 14:51:35 2012 - [info] Dead Servers: Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.13(192.168.123.13:3306) Wed Jun? 6 14:51:35 2012 - [info] Alive Servers: Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.14(192.168.123.14:3306) Wed Jun? 6 14:51:35 2012 - [info] Alive Slaves: Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.14(192.168.123.14:3306)? Version=5.5.25-log (oldest major version between slaves) log-bin:enabled Wed Jun? 6 14:51:35 2012 - [info]???? Replicating from 192.168.123.13(192.168.123.13:3306) Wed Jun? 6 14:51:35 2012 - [info]???? Primary candidate for the new Master (candidate_master is set) Wed Jun? 6 14:51:35 2012 - [info] Checking slave configurations.. Wed Jun? 6 14:51:35 2012 - [warning]? read_only=1 is not set on slave 192.168.123.14(192.168.123.14:3306). Wed Jun? 6 14:51:35 2012 - [warning]? relay_log_purge=0 is not set on slave 192.168.123.14(192.168.123.14:3306). Wed Jun? 6 14:51:35 2012 - [info] Checking replication filtering settings.. Wed Jun? 6 14:51:35 2012 - [info]? Replication filtering check ok. Wed Jun? 6 14:51:35 2012 - [info] Master is down! Wed Jun? 6 14:51:35 2012 - [info] Terminating monitoring script. Wed Jun? 6 14:51:35 2012 - [info] Got exit code 20 (Master dead). Wed Jun? 6 14:51:35 2012 - [info] MHA::MasterFailover version 0.52. Wed Jun? 6 14:51:35 2012 - [info] Starting master failover. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] * Phase 1: Configuration Check Phase.. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] Dead Servers: Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.13(192.168.123.13:3306) Wed Jun? 6 14:51:35 2012 - [info] Checking master reachability via mysql(double check).. Wed Jun? 6 14:51:35 2012 - [info]? ok. Wed Jun? 6 14:51:35 2012 - [info] Alive Servers: Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.14(192.168.123.14:3306) Wed Jun? 6 14:51:35 2012 - [info] Alive Slaves: Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.14(192.168.123.14:3306)? Version=5.5.25-log (oldest major version between slaves) log-bin:enabled Wed Jun? 6 14:51:35 2012 - [info]???? Replicating from 192.168.123.13(192.168.123.13:3306) Wed Jun? 6 14:51:35 2012 - [info]???? Primary candidate for the new Master (candidate_master is set) Wed Jun? 6 14:51:35 2012 - [info] ** Phase 1: Configuration Check Phase completed. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] * Phase 2: Dead Master Shutdown Phase.. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] Forcing shutdown so that applications never connect to the current master.. Wed Jun? 6 14:51:35 2012 - [warning] master_ip_failover_script is not set. Skipping invalidating dead master ip address. Wed Jun? 6 14:51:35 2012 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master. Wed Jun? 6 14:51:35 2012 - [info] * Phase 2: Dead Master Shutdown Phase completed. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] * Phase 3: Master Recovery Phase.. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] * Phase 3.1: Getting Latest Slaves Phase.. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] The latest binary log file/position on all slaves is mysql-bin.000021:107 Wed Jun? 6 14:51:35 2012 - [info] Latest slaves (Slaves that received relay log files to the latest): Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.14(192.168.123.14:3306)? Version=5.5.25-log (oldest major version between slaves) log-bin:enabled Wed Jun? 6 14:51:35 2012 - [info]???? Replicating from 192.168.123.13(192.168.123.13:3306) Wed Jun? 6 14:51:35 2012 - [info]???? Primary candidate for the new Master (candidate_master is set) Wed Jun? 6 14:51:35 2012 - [info] The oldest binary log file/position on all slaves is mysql-bin.000021:107 Wed Jun? 6 14:51:35 2012 - [info] Oldest slaves: Wed Jun? 6 14:51:35 2012 - [info]?? 192.168.123.14(192.168.123.14:3306)? Version=5.5.25-log (oldest major version between slaves) log-bin:enabled Wed Jun? 6 14:51:35 2012 - [info]???? Replicating from 192.168.123.13(192.168.123.13:3306) Wed Jun? 6 14:51:35 2012 - [info]???? Primary candidate for the new Master (candidate_master is set) Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase.. Wed Jun? 6 14:51:35 2012 - [info] Wed Jun? 6 14:51:35 2012 - [info] Fetching dead master's binary logs.. Wed Jun? 6 14:51:35 2012 - [info] Executing command on the dead master 192.168.123.13(192.168.123.13:3306): save_binary_logs --command=save --start_file=mysql-bin.000021? --start_pos=107 --binlog_dir=/mydata --output_file=/var/tmp/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.52 ? Creating /var/tmp if not exists..??? ok. ?Concat binary/relay logs from mysql-bin.000021 pos 107 to mysql-bin.000021 EOF into /var/tmp/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog .. ? Dumping binlog format description event, from position 0 to 107.. ok. ? Dumping effective binlog data from /mydata/mysql-bin.000021 position 107 to tail(126).. ok. ?Concat succeeded. Wed Jun? 6 14:51:36 2012 - [info] scp from root@192.168.123.13:/var/tmp/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog to local:/masterha/app1/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog succeeded. Wed Jun? 6 14:51:36 2012 - [info] HealthCheck: SSH to 192.168.123.14 is reachable. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] * Phase 3.3: Determining New Master Phase.. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] Finding the latest slave that has all relay logs for recovering other slaves.. Wed Jun? 6 14:51:37 2012 - [info] All slaves received relay logs to the same position. No need to resync each other. Wed Jun? 6 14:51:37 2012 - [info] Searching new master from slaves.. Wed Jun? 6 14:51:37 2012 - [info]? Candidate masters from the configuration file: Wed Jun? 6 14:51:37 2012 - [info]?? 192.168.123.14(192.168.123.14:3306)? Version=5.5.25-log (oldest major version between slaves) log-bin:enabled Wed Jun? 6 14:51:37 2012 - [info]???? Replicating from 192.168.123.13(192.168.123.13:3306) Wed Jun? 6 14:51:37 2012 - [info]???? Primary candidate for the new Master (candidate_master is set) Wed Jun? 6 14:51:37 2012 - [info]? Non-candidate masters: Wed Jun? 6 14:51:37 2012 - [info]? Searching from candidate_master slaves which have received the latest relay log events.. Wed Jun? 6 14:51:37 2012 - [info] New master is 192.168.123.14(192.168.123.14:3306) Wed Jun? 6 14:51:37 2012 - [info] Starting master failover.. Wed Jun? 6 14:51:37 2012 - [info] From: 192.168.123.13 (current master) ?+--192.168.123.14
To: 192.168.123.14 (new master) Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] * Phase 3.3: New Master Diff Log Generation Phase.. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info]? This server has all relay logs. No need to generate diff files from the latest slave. Wed Jun? 6 14:51:37 2012 - [info] Sending binlog.. Wed Jun? 6 14:51:37 2012 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog to root@192.168.123.14:/var/tmp/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog succeeded. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] * Phase 3.4: Master Log Apply Phase.. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed. Wed Jun? 6 14:51:37 2012 - [info] Starting recovery on 192.168.123.14(192.168.123.14:3306).. Wed Jun? 6 14:51:37 2012 - [info]? Generating diffs succeeded. Wed Jun? 6 14:51:37 2012 - [info] Waiting until all relay logs are applied. Wed Jun? 6 14:51:37 2012 - [info]? done. Wed Jun? 6 14:51:37 2012 - [info] Getting slave status.. Wed Jun? 6 14:51:37 2012 - [info] This slave(192.168.123.14)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000021:107). No need to recover from Exec_Master_Log_Pos. Wed Jun? 6 14:51:37 2012 - [info] Connecting to the target slave host 192.168.123.14, running recover script.. Wed Jun? 6 14:51:37 2012 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user=root --slave_host=192.168.123.14 --slave_ip=192.168.123.14? --slave_port=3306 --apply_files=/var/tmp/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog --workdir=/var/tmp --target_version=5.5.25-log --timestamp=20120606145135 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.52 --slave_pass=xxx Wed Jun? 6 14:51:37 2012 - [info] Applying differential binary/relay log files /var/tmp/saved_master_binlog_from_192.168.123.13_3306_20120606145135.binlog on 192.168.123.14:3306. This may take long time... Applying log files succeeded. Wed Jun? 6 14:51:37 2012 - [info]? All relay logs were successfully applied. Wed Jun? 6 14:51:37 2012 - [info] Getting new master's binlog name and position.. Wed Jun? 6 14:51:37 2012 - [info]? mysql-bin.000023:107 Wed Jun? 6 14:51:37 2012 - [info]? All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.123.14', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000023', MASTER_LOG_POS=107, MASTER_USER='r_test', MASTER_PASSWORD='xxx'; Wed Jun? 6 14:51:37 2012 - [warning] master_ip_failover_script is not set. Skipping taking over new master ip address. Wed Jun? 6 14:51:37 2012 - [info] ** Finished master recovery successfully. Wed Jun? 6 14:51:37 2012 - [info] * Phase 3: Master Recovery Phase completed. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] * Phase 4: Slaves Recovery Phase.. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase.. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] Generating relay diff files from the latest slave succeeded. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase.. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] All new slave servers recovered successfully. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] * Phase 5: New master cleanup phease.. Wed Jun? 6 14:51:37 2012 - [info] Wed Jun? 6 14:51:37 2012 - [info] Resetting slave info on the new master.. Wed Jun? 6 14:51:37 2012 - [info] Master failover to 192.168.123.14(192.168.123.14:3306) completed successfully. Wed Jun? 6 14:51:37 2012 - [info]
----- Failover Report -----
app1: MySQL Master failover 192.168.123.13 to 192.168.123.14 succeeded
Master 192.168.123.13 is down!
Check MHA Manager logs at dg55.yang.com:/masterha/app1/manager.log for details.
Started automated(non-interactive) failover. The latest slave 192.168.123.14(192.168.123.14:3306) has all relay logs for recovery. Selected 192.168.123.14 as a new master. 192.168.123.14: OK: Applying all logs succeeded. Generating relay diff files from the latest slave succeeded. 192.168.123.14: Resetting slave info succeeded. Master failover to 192.168.123.14(192.168.123.14:3306) completed successfully.