MHA FailOver log.

manager.log

Mon Mar 10 17:41:08 2014 - [warning] Got error on MySQL ping: 2006 (MySQL server has gone away)
ssh: connect to host 10.0.0.1 port 22: Connection refused
Mon Mar 10 17:41:08 2014 - [warning] HealthCheck: SSH to mysqlserver-a is NOT reachable.
Mon Mar 10 17:41:11 2014 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Mon Mar 10 17:41:11 2014 - [warning] Connection failed 1 time(s)..
Mon Mar 10 17:41:14 2014 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Mon Mar 10 17:41:14 2014 - [warning] Connection failed 2 time(s)..
Mon Mar 10 17:41:17 2014 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Mon Mar 10 17:41:17 2014 - [warning] Connection failed 3 time(s)..
Mon Mar 10 17:41:17 2014 - [warning] Master is not reachable from health checker!
Mon Mar 10 17:41:17 2014 - [warning] Master mysqlserver-a(10.0.0.1:3306) is not reachable!
Mon Mar 10 17:41:17 2014 - [warning] SSH is NOT reachable.
Mon Mar 10 17:41:17 2014 - [info] Connecting to a master server failed. Reading configuration file /etc/masterha_default.cnf and /etc/mha4mysql/manager.conf again, and trying to connect to all servers to check server status..
Mon Mar 10 17:41:17 2014 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Mon Mar 10 17:41:17 2014 - [info] Reading application default configurations from /etc/mha4mysql/manager.conf..
Mon Mar 10 17:41:17 2014 - [info] Reading server configurations from /etc/mha4mysql/manager.conf..
Mon Mar 10 17:41:17 2014 - [warning] SQL Thread is stopped(no error) on mysqlserver-b(10.0.0.2:3306)
Mon Mar 10 17:41:17 2014 - [warning] SQL Thread is stopped(no error) on mysqlserver-c(10.0.0.3:3306)
Mon Mar 10 17:41:17 2014 - [info] Dead Servers:
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-a(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info] Alive Servers:
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-b(10.0.0.2:3306)
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-c(10.0.0.3:3306)
Mon Mar 10 17:41:17 2014 - [info] Alive Slaves:
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-b(10.0.0.2:3306)  Version=5.6.16-log (oldest major version between slaves) log-bin:enabled
Mon Mar 10 17:41:17 2014 - [info]     Replicating from 10.0.0.1(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-c(10.0.0.3:3306)  Version=5.6.16-log (oldest major version between slaves) log-bin:enabled
Mon Mar 10 17:41:17 2014 - [info]     Replicating from 10.0.0.1(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info] Checking slave configurations..
Mon Mar 10 17:41:17 2014 - [warning]  read_only=1 is not set on slave mysqlserver-b(10.0.0.2:3306).
Mon Mar 10 17:41:17 2014 - [warning]  relay_log_purge=0 is not set on slave mysqlserver-b(10.0.0.2:3306).
Mon Mar 10 17:41:17 2014 - [warning]  read_only=1 is not set on slave mysqlserver-c(10.0.0.3:3306).
Mon Mar 10 17:41:17 2014 - [warning]  relay_log_purge=0 is not set on slave mysqlserver-c(10.0.0.3:3306).
Mon Mar 10 17:41:17 2014 - [info] Checking replication filtering settings..
Mon Mar 10 17:41:17 2014 - [info]  Replication filtering check ok.
Mon Mar 10 17:41:17 2014 - [info] Master is down!
Mon Mar 10 17:41:17 2014 - [info] Terminating monitoring script.
Mon Mar 10 17:41:17 2014 - [info] Got exit code 20 (Master dead).
Mon Mar 10 17:41:17 2014 - [info] MHA::MasterFailover version 0.52.
Mon Mar 10 17:41:17 2014 - [info] Starting master failover.
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] * Phase 1: Configuration Check Phase..
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [warning] SQL Thread is stopped(no error) on mysqlserver-b(10.0.0.2:3306)
Mon Mar 10 17:41:17 2014 - [warning] SQL Thread is stopped(no error) on mysqlserver-c(10.0.0.3:3306)
Mon Mar 10 17:41:17 2014 - [info] Dead Servers:
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-a(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info] Checking master reachability via mysql(double check)..
Mon Mar 10 17:41:17 2014 - [info]  ok.
Mon Mar 10 17:41:17 2014 - [info] Alive Servers:
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-b(10.0.0.2:3306)
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-c(10.0.0.3:3306)
Mon Mar 10 17:41:17 2014 - [info] Alive Slaves:
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-b(10.0.0.2:3306)  Version=5.6.16-log (oldest major version between slaves) log-bin:enabled
Mon Mar 10 17:41:17 2014 - [info]     Replicating from 10.0.0.1(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-c(10.0.0.3:3306)  Version=5.6.16-log (oldest major version between slaves) log-bin:enabled
Mon Mar 10 17:41:17 2014 - [info]     Replicating from 10.0.0.1(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info]  Starting SQL thread on mysqlserver-b(10.0.0.2:3306) ..
Mon Mar 10 17:41:17 2014 - [info]   done.
Mon Mar 10 17:41:17 2014 - [info]  Starting SQL thread on mysqlserver-c(10.0.0.3:3306) ..
Mon Mar 10 17:41:17 2014 - [info]   done.
Mon Mar 10 17:41:17 2014 - [info] ** Phase 1: Configuration Check Phase completed.
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] * Phase 2: Dead Master Shutdown Phase..
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] Forcing shutdown so that applications never connect to the current master..
Mon Mar 10 17:41:17 2014 - [info] Executing master IP deactivatation script:
Mon Mar 10 17:41:17 2014 - [info]   /etc/mha4mysql/scripts/rewrite_haproxy_config.rb --orig_master_host=mysqlserver-a --orig_master_ip=10.0.0.1 --orig_master_port=3306 --command=stop
Mon Mar 10 17:41:17 2014 - [info]  done.
Mon Mar 10 17:41:17 2014 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Mon Mar 10 17:41:17 2014 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] * Phase 3: Master Recovery Phase..
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] The latest binary log file/position on all slaves is mysqld-bin.000007:24179
Mon Mar 10 17:41:17 2014 - [info] Latest slaves (Slaves that received relay log files to the latest):
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-b(10.0.0.2:3306)  Version=5.6.16-log (oldest major version between slaves) log-bin:enabled
Mon Mar 10 17:41:17 2014 - [info]     Replicating from 10.0.0.1(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info] The oldest binary log file/position on all slaves is mysqld-bin.000007:23133
Mon Mar 10 17:41:17 2014 - [info] Oldest slaves:
Mon Mar 10 17:41:17 2014 - [info]   mysqlserver-c(10.0.0.3:3306)  Version=5.6.16-log (oldest major version between slaves) log-bin:enabled
Mon Mar 10 17:41:17 2014 - [info]     Replicating from 10.0.0.1(10.0.0.1:3306)
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 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.
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] * Phase 3.3: Determining New Master Phase..
Mon Mar 10 17:41:17 2014 - [info] 
Mon Mar 10 17:41:17 2014 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Mon Mar 10 17:41:18 2014 - [info] HealthCheck: SSH to mysqlserver-b is reachable.
Mon Mar 10 17:41:18 2014 - [info] Checking whether mysqlserver-b has relay logs from the oldest position..
Mon Mar 10 17:41:18 2014 - [info] Executing command: apply_diff_relay_logs --command=find --latest_mlf=mysqld-bin.000007 --latest_rmlp=24179 --target_mlf=mysqld-bin.000007 --target_rmlp=23133 --server_id=2 --workdir=/var/log/mha4mysql/ --timestamp=20140310174117 --manager_version=0.52 --relay_log_info=/var/lib/mysql/relay-log.info  :
    Opening /var/lib/mysql/relay-log.info ... ok.
    Relay log found at /var/lib/mysql, up to mysqlserver-b-relay-bin.000002
 Fast relay log position search succeeded.
 Target relay log file/position found. start_file:mysqlserver-b-relay-bin.000002, start_pos:9926.
Target relay log FOUND!
Mon Mar 10 17:41:18 2014 - [info] OK. mysqlserver-b has all relay logs.
Mon Mar 10 17:41:18 2014 - [info] HealthCheck: SSH to mysqlserver-c is reachable.
Mon Mar 10 17:41:19 2014 - [info] Searching new master from slaves..
Mon Mar 10 17:41:19 2014 - [info]  Candidate masters from the configuration file:
Mon Mar 10 17:41:19 2014 - [info]  Non-candidate masters:
Mon Mar 10 17:41:19 2014 - [info] New master is mysqlserver-b(10.0.0.2:3306)
Mon Mar 10 17:41:19 2014 - [info] Starting master failover..
Mon Mar 10 17:41:19 2014 - [info] 
From:
mysqlserver-a (current master)
 +--mysqlserver-b
 +--mysqlserver-c

To:
mysqlserver-b (new master)
 +--mysqlserver-c
Mon Mar 10 17:41:19 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Mon Mar 10 17:41:19 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info]  This server has all relay logs. No need to generate diff files from the latest slave.
Mon Mar 10 17:41:19 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info] * Phase 3.4: Master Log Apply Phase..
Mon Mar 10 17:41:19 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Mon Mar 10 17:41:19 2014 - [info] Starting recovery on mysqlserver-b(10.0.0.2:3306)..
Mon Mar 10 17:41:19 2014 - [info]  This server has all relay logs. Waiting all logs to be applied.. 
Mon Mar 10 17:41:19 2014 - [info]   done.
Mon Mar 10 17:41:19 2014 - [info]  All relay logs were successfully applied.
Mon Mar 10 17:41:19 2014 - [info] Getting new master's binlog name and position..
Mon Mar 10 17:41:19 2014 - [info]  mysqld-bin.000008:61046
Mon Mar 10 17:41:19 2014 - [info]  All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='mysqlserver-b or 10.0.0.2', MASTER_PORT=3306, MASTER_LOG_FILE='mysqld-bin.000008', MASTER_LOG_POS=61046, MASTER_USER='repluser', MASTER_PASSWORD='xxx';
Mon Mar 10 17:41:19 2014 - [info] Executing master IP activate script:
Mon Mar 10 17:41:19 2014 - [info]   /etc/mha4mysql/scripts/rewrite_haproxy_config.rb --command=start -ssh_user=root --orig_master_host=mysqlserver-a --orig_master_ip=10.0.0.1 --orig_master_port=3306 --new_master_host=mysqlserver-b --new_master_ip=10.0.0.2 --new_master_port=3306
Mon Mar 10 17:41:19 2014 - [info]  OK.
Mon Mar 10 17:41:19 2014 - [info] ** Finished master recovery successfully.
Mon Mar 10 17:41:19 2014 - [info] * Phase 3: Master Recovery Phase completed.
Mon Mar 10 17:41:19 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info] * Phase 4: Slaves Recovery Phase..
Mon Mar 10 17:41:19 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Mon Mar 10 17:41:19 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info] -- Slave diff file generation on host mysqlserver-c(10.0.0.3:3306) started, pid: 11616. Check tmp log /var/log/mha4mysql//mysqlserver-c_3306_20140310174117.log if it takes time..
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:20 2014 - [info] Log messages from mysqlserver-c ...
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:19 2014 - [info] Server mysqlserver-c received relay logs up to: mysqld-bin.000007:23133
Mon Mar 10 17:41:19 2014 - [info] Need to get diffs from the latest slave(mysqlserver-b) up to: mysqld-bin.000007:24179 (using the latest slave's relay logs)
Mon Mar 10 17:41:19 2014 - [info] Connecting to the latest slave host mysqlserver-b, generating diff relay log files..
Mon Mar 10 17:41:19 2014 - [info] Executing command: apply_diff_relay_logs --command=generate_and_send --scp_user=root --scp_host=10.0.0.3 --latest_mlf=mysqld-bin.000007 --latest_rmlp=24179 --target_mlf=mysqld-bin.000007 --target_rmlp=23133 --server_id=2 --diff_file_readtolatest=/var/log/mha4mysql//relay_from_read_to_latest_mysqlserver-c_3306_20140310174117.binlog --workdir=/var/log/mha4mysql/ --timestamp=20140310174117 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.52 --relay_log_info=/var/lib/mysql/relay-log.info 
Mon Mar 10 17:41:20 2014 - [info] 
    Opening /var/lib/mysql/relay-log.info ... ok.
    Relay log found at /var/lib/mysql, up to mysqlserver-b-relay-bin.000002
 Fast relay log position search succeeded.
 Target relay log file/position found. start_file:mysqlserver-b-relay-bin.000002, start_pos:9926.
 Concat binary/relay logs from mysqlserver-b-relay-bin.000002 pos 9926 to mysqlserver-b-relay-bin.000002 EOF into /var/log/mha4mysql//relay_from_read_to_latest_mysqlserver-c_3306_20140310174117.binlog ..
  Dumping binlog format description event, from position 0 to 284.. ok.
  Dumping effective binlog data from /var/lib/mysql/mysqlserver-b-relay-bin.000002 position 9926 to tail(10972).. ok.
 Concat succeeded.
 Generating diff relay log succeeded. Saved at /var/log/mha4mysql//relay_from_read_to_latest_mysqlserver-c_3306_20140310174117.binlog .
 scp mysqlserver-b:/var/log/mha4mysql//relay_from_read_to_latest_mysqlserver-c_3306_20140310174117.binlog to root@10.0.0.3 succeeded.
Mon Mar 10 17:41:20 2014 - [info]  Generating diff files succeeded.
Mon Mar 10 17:41:20 2014 - [info] End of log messages from mysqlserver-c.
Mon Mar 10 17:41:20 2014 - [info] -- Slave diff log generation on host mysqlserver-c(10.0.0.3:3306) succeeded.
Mon Mar 10 17:41:20 2014 - [info] Generating relay diff files from the latest slave succeeded.
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:20 2014 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:20 2014 - [info] -- Slave recovery on host mysqlserver-c(10.0.0.3:3306) started, pid: 11623. Check tmp log /var/log/mha4mysql//mysqlserver-c_3306_20140310174117.log if it takes time..
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:20 2014 - [info] Log messages from mysqlserver-c ...
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:20 2014 - [info] Starting recovery on mysqlserver-c(10.0.0.3:3306)..
Mon Mar 10 17:41:20 2014 - [info]  Generating diffs succeeded.
Mon Mar 10 17:41:20 2014 - [info] Waiting until all relay logs are applied.
Mon Mar 10 17:41:20 2014 - [info]  done.
Mon Mar 10 17:41:20 2014 - [info] Getting slave status..
Mon Mar 10 17:41:20 2014 - [info] This slave(mysqlserver-c)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysqld-bin.000007:23133). No need to recover from Exec_Master_Log_Pos.
Mon Mar 10 17:41:20 2014 - [info] Connecting to the target slave host mysqlserver-c, running recover script..
Mon Mar 10 17:41:20 2014 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user=root --slave_host=mysqlserver-c --slave_ip=10.0.0.3  --slave_port=3306 --apply_files=/var/log/mha4mysql//relay_from_read_to_latest_mysqlserver-c_3306_20140310174117.binlog --workdir=/var/log/mha4mysql/ --target_version=5.6.16-log --timestamp=20140310174117 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.52 --slave_pass=xxx
Mon Mar 10 17:41:20 2014 - [info] 
Applying differential binary/relay log files /var/log/mha4mysql//relay_from_read_to_latest_mysqlserver-c_3306_20140310174117.binlog on mysqlserver-c:3306. This may take long time...
Applying log files succeeded.
Mon Mar 10 17:41:20 2014 - [info]  All relay logs were successfully applied.
Mon Mar 10 17:41:20 2014 - [info]  Resetting slave mysqlserver-c(10.0.0.3:3306) and starting replication from the new master mysqlserver-b(10.0.0.2:3306)..
Mon Mar 10 17:41:20 2014 - [info]  Executed CHANGE MASTER.
Mon Mar 10 17:41:20 2014 - [info]  Slave started.
Mon Mar 10 17:41:20 2014 - [info] End of log messages from mysqlserver-c.
Mon Mar 10 17:41:20 2014 - [info] -- Slave recovery on host mysqlserver-c(10.0.0.3:3306) succeeded.
Mon Mar 10 17:41:20 2014 - [info] All new slave servers recovered successfully.
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:20 2014 - [info] * Phase 5: New master cleanup phease..
Mon Mar 10 17:41:20 2014 - [info] 
Mon Mar 10 17:41:20 2014 - [info] Resetting slave info on the new master..
Mon Mar 10 17:41:21 2014 - [info] Master failover to mysqlserver-b(10.0.0.2:3306) completed successfully.
Mon Mar 10 17:41:21 2014 - [info] 

----- Failover Report -----

manager: MySQL Master failover mysqlserver-a to mysqlserver-b succeeded

Master mysqlserver-a is down!

Check MHA Manager logs at managerserver:/var/log/mha4mysql/manager.log for details.

Started automated(non-interactive) failover.
Invalidated master IP address on mysqlserver-a.
The latest slave mysqlserver-b(10.0.0.2:3306) has all relay logs for recovery.
Selected mysqlserver-b as a new master.
mysqlserver-b: OK: Applying all logs succeeded.
mysqlserver-b: OK: Activated master IP address.
mysqlserver-c: Generating differential relay logs up to mysqlserver-b succeeded.
Generating relay diff files from the latest slave succeeded.
mysqlserver-c: OK: Applying all logs succeeded. Slave started, replicating from mysqlserver-b.
mysqlserver-b: Resetting slave info succeeded.
Master failover to mysqlserver-b(10.0.0.2:3306) completed successfully.