Wed Aug 20 18:30:57 2014 - [warning] Got error on MySQL select ping: 2006 (MySQL server has gone away)
Wed Aug 20 18:30:57 2014 - [info] Executing SSH check script: save_binary_logs --command=test --start_pos=4 --binlog_dir=/mysql/data/mysql5610/log --output_file=/var/tmp/save_binary_logs_test --manager_version=0.56 --binlog_prefix=mysql-bin
Wed Aug 20 18:30:57 2014 - [info] Executing secondary network check script: masterha_secondary_check -s 192.168.1.65 -s 192.168.1.66 -s 192.168.1.67  --user=root  --master_host=192.168.1.65  --master_ip=192.168.1.65  --master_port=3388 --master_user=root --master_password=dhgate123 --ping_type=SELECT
Wed Aug 20 18:30:57 2014 - [info] HealthCheck: SSH to 192.168.1.65 is reachable.
Monitoring server 192.168.1.65 is reachable, Master is not reachable from 192.168.1.65. OK.
Monitoring server 192.168.1.66 is reachable, Master is not reachable from 192.168.1.66. OK.
Monitoring server 192.168.1.67 is reachable, Master is not reachable from 192.168.1.67. OK.
Wed Aug 20 18:30:58 2014 - [info] Master is not reachable from all other monitoring servers. Failover should start.
Wed Aug 20 18:31:00 2014 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Wed Aug 20 18:31:00 2014 - [warning] Connection failed 2 time(s)..
Wed Aug 20 18:31:03 2014 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Wed Aug 20 18:31:03 2014 - [warning] Connection failed 3 time(s)..
Wed Aug 20 18:31:06 2014 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Wed Aug 20 18:31:06 2014 - [warning] Connection failed 4 time(s)..
Wed Aug 20 18:31:06 2014 - [warning] Master is not reachable from health checker!
Wed Aug 20 18:31:06 2014 - [warning] Master 192.168.1.65(192.168.1.65:3388) is not reachable!
Wed Aug 20 18:31:06 2014 - [warning] SSH is reachable.
Wed Aug 20 18:31:06 2014 - [info] Connecting to a master server failed. Reading configuration file /masterha/conf/masterha_default.cnf and /masterha/conf/app1/app1.cnf again, and trying to connect to all servers to check server status..
Wed Aug 20 18:31:06 2014 - [info] Reading default configuration from /masterha/conf/masterha_default.cnf..
Wed Aug 20 18:31:06 2014 - [info] Reading application default configuration from /masterha/conf/app1/app1.cnf..
Wed Aug 20 18:31:06 2014 - [info] Reading server configuration from /masterha/conf/app1/app1.cnf..
Wed Aug 20 18:31:06 2014 - [warning] SQL Thread is stopped(no error) on 192.168.1.66(192.168.1.66:3388)
Wed Aug 20 18:31:06 2014 - [warning] SQL Thread is stopped(no error) on 192.168.1.67(192.168.1.67:3388)
Wed Aug 20 18:31:06 2014 - [info] GTID failover mode = 0
Wed Aug 20 18:31:06 2014 - [info] Dead Servers:
Wed Aug 20 18:31:06 2014 - [info]   192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:06 2014 - [info] Alive Servers:
Wed Aug 20 18:31:06 2014 - [info]   192.168.1.66(192.168.1.66:3388)
Wed Aug 20 18:31:06 2014 - [info]   192.168.1.67(192.168.1.67:3388)
Wed Aug 20 18:31:06 2014 - [info] Alive Slaves:
Wed Aug 20 18:31:06 2014 - [info]   192.168.1.66(192.168.1.66:3388)  Version=5.6.10-log (oldest major version between slaves) log-bin:enabled
Wed Aug 20 18:31:06 2014 - [info]     Replicating from 192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:06 2014 - [info]     Primary candidate for the new Master (candidate_master is set)
Wed Aug 20 18:31:06 2014 - [info]   192.168.1.67(192.168.1.67:3388)  Version=5.6.10-log (oldest major version between slaves) log-bin:enabled
Wed Aug 20 18:31:06 2014 - [info]     Replicating from 192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:06 2014 - [info] Checking slave configurations..
Wed Aug 20 18:31:06 2014 - [info]  read_only=1 is not set on slave 192.168.1.66(192.168.1.66:3388).
Wed Aug 20 18:31:06 2014 - [warning]  relay_log_purge=0 is not set on slave 192.168.1.66(192.168.1.66:3388).
Wed Aug 20 18:31:06 2014 - [info]  read_only=1 is not set on slave 192.168.1.67(192.168.1.67:3388).
Wed Aug 20 18:31:06 2014 - [warning]  relay_log_purge=0 is not set on slave 192.168.1.67(192.168.1.67:3388).
Wed Aug 20 18:31:06 2014 - [info] Checking replication filtering settings..
Wed Aug 20 18:31:06 2014 - [info]  Replication filtering check ok.
Wed Aug 20 18:31:06 2014 - [info] Master is down!
Wed Aug 20 18:31:06 2014 - [info] Terminating monitoring script.
Wed Aug 20 18:31:06 2014 - [info] Got exit code 20 (Master dead).
Wed Aug 20 18:31:06 2014 - [info] MHA::MasterFailover version 0.56.
Wed Aug 20 18:31:06 2014 - [info] Starting master failover.
Wed Aug 20 18:31:06 2014 - [info] 
Wed Aug 20 18:31:06 2014 - [info] * Phase 1: Configuration Check Phase..
Wed Aug 20 18:31:06 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [warning] SQL Thread is stopped(no error) on 192.168.1.66(192.168.1.66:3388)
Wed Aug 20 18:31:07 2014 - [warning] SQL Thread is stopped(no error) on 192.168.1.67(192.168.1.67:3388)
Wed Aug 20 18:31:07 2014 - [info] GTID failover mode = 0
Wed Aug 20 18:31:07 2014 - [info] Dead Servers:
Wed Aug 20 18:31:07 2014 - [info]   192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:07 2014 - [info] Checking master reachability via MySQL(double check)...
Wed Aug 20 18:31:07 2014 - [info]  ok.
Wed Aug 20 18:31:07 2014 - [info] Alive Servers:
Wed Aug 20 18:31:07 2014 - [info]   192.168.1.66(192.168.1.66:3388)
Wed Aug 20 18:31:07 2014 - [info]   192.168.1.67(192.168.1.67:3388)
Wed Aug 20 18:31:07 2014 - [info] Alive Slaves:
Wed Aug 20 18:31:07 2014 - [info]   192.168.1.66(192.168.1.66:3388)  Version=5.6.10-log (oldest major version between slaves) log-bin:enabled
Wed Aug 20 18:31:07 2014 - [info]     Replicating from 192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:07 2014 - [info]     Primary candidate for the new Master (candidate_master is set)
Wed Aug 20 18:31:07 2014 - [info]   192.168.1.67(192.168.1.67:3388)  Version=5.6.10-log (oldest major version between slaves) log-bin:enabled
Wed Aug 20 18:31:07 2014 - [info]     Replicating from 192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:07 2014 - [info]  Starting SQL thread on 192.168.1.66(192.168.1.66:3388) ..
Wed Aug 20 18:31:07 2014 - [info]   done.
Wed Aug 20 18:31:07 2014 - [info]  Starting SQL thread on 192.168.1.67(192.168.1.67:3388) ..
Wed Aug 20 18:31:07 2014 - [info]   done.
Wed Aug 20 18:31:07 2014 - [info] Starting Non-GTID based failover.
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] ** Phase 1: Configuration Check Phase completed.
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] * Phase 2: Dead Master Shutdown Phase..
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] Forcing shutdown so that applications never connect to the current master..
Wed Aug 20 18:31:07 2014 - [warning] master_ip_failover_script is not set. Skipping invalidating dead master IP address.
Wed Aug 20 18:31:07 2014 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Wed Aug 20 18:31:07 2014 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] * Phase 3: Master Recovery Phase..
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] The latest binary log file/position on all slaves is mysql-bin.000018:3330
Wed Aug 20 18:31:07 2014 - [info] Latest slaves (Slaves that received relay log files to the latest):
Wed Aug 20 18:31:07 2014 - [info]   192.168.1.66(192.168.1.66:3388)  Version=5.6.10-log (oldest major version between slaves) log-bin:enabled
Wed Aug 20 18:31:07 2014 - [info]     Replicating from 192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:07 2014 - [info]     Primary candidate for the new Master (candidate_master is set)
Wed Aug 20 18:31:07 2014 - [info] The oldest binary log file/position on all slaves is mysql-bin.000018:120
Wed Aug 20 18:31:07 2014 - [info] Oldest slaves:
Wed Aug 20 18:31:07 2014 - [info]   192.168.1.67(192.168.1.67:3388)  Version=5.6.10-log (oldest major version between slaves) log-bin:enabled
Wed Aug 20 18:31:07 2014 - [info]     Replicating from 192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..
Wed Aug 20 18:31:07 2014 - [info] 
Wed Aug 20 18:31:07 2014 - [info] Fetching dead master's binary logs..
Wed Aug 20 18:31:07 2014 - [info] Executing command on the dead master 192.168.1.65(192.168.1.65:3388): save_binary_logs --command=save --start_file=mysql-bin.000018  --start_pos=3330 --binlog_dir=/mysql/data/mysql5610/log --output_file=/var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56
  Creating /var/tmp if not exists..    ok.
 Concat binary/relay logs from mysql-bin.000018 pos 3330 to mysql-bin.000018 EOF into /var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog ..
  Dumping binlog format description event, from position 0 to 120.. ok.
  Dumping effective binlog data from /mysql/data/mysql5610/log/mysql-bin.000018 position 3330 to tail(5065).. ok.
 Concat succeeded.
Wed Aug 20 18:31:07 2014 - [info] scp from root@192.168.1.65:/var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog to local:/masterha/app1/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog succeeded.
Wed Aug 20 18:31:08 2014 - [info] HealthCheck: SSH to 192.168.1.66 is reachable.
Wed Aug 20 18:31:08 2014 - [info] HealthCheck: SSH to 192.168.1.67 is reachable.
Wed Aug 20 18:31:08 2014 - [info] 
Wed Aug 20 18:31:08 2014 - [info] * Phase 3.3: Determining New Master Phase..
Wed Aug 20 18:31:08 2014 - [info] 
Wed Aug 20 18:31:08 2014 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Wed Aug 20 18:31:08 2014 - [info] Checking whether 192.168.1.66 has relay logs from the oldest position..
Wed Aug 20 18:31:08 2014 - [info] Executing command: apply_diff_relay_logs --command=find --latest_mlf=mysql-bin.000018 --latest_rmlp=3330 --target_mlf=mysql-bin.000018 --target_rmlp=120 --server_id=2 --workdir=/var/tmp --timestamp=20140820183106 --manager_version=0.56 --relay_log_info=/mysql/data/mysql5610/data/relay-log.info  --relay_dir=/mysql/data/mysql5610/data/  :
    Opening /mysql/data/mysql5610/data/relay-log.info ... ok.
    Relay log found at /mysql/data/mysql5610/data, up to localhost-relay-bin.000002
 Fast relay log position search succeeded.
 Target relay log file/position found. start_file:localhost-relay-bin.000002, start_pos:283.
Target relay log FOUND!
Wed Aug 20 18:31:08 2014 - [info] OK. 192.168.1.66 has all relay logs.
Wed Aug 20 18:31:08 2014 - [info] Searching new master from slaves..
Wed Aug 20 18:31:08 2014 - [info]  Candidate masters from the configuration file:
Wed Aug 20 18:31:08 2014 - [info]   192.168.1.66(192.168.1.66:3388)  Version=5.6.10-log (oldest major version between slaves) log-bin:enabled
Wed Aug 20 18:31:08 2014 - [info]     Replicating from 192.168.1.65(192.168.1.65:3388)
Wed Aug 20 18:31:08 2014 - [info]     Primary candidate for the new Master (candidate_master is set)
Wed Aug 20 18:31:08 2014 - [info]  Non-candidate masters:
Wed Aug 20 18:31:08 2014 - [info]  Searching from candidate_master slaves which have received the latest relay log events..
Wed Aug 20 18:31:08 2014 - [info] New master is 192.168.1.66(192.168.1.66:3388)
Wed Aug 20 18:31:08 2014 - [info] Starting master failover..
Wed Aug 20 18:31:08 2014 - [info] 
From:
192.168.1.65(192.168.1.65:3388) (current master)
 +--192.168.1.66(192.168.1.66:3388)
 +--192.168.1.67(192.168.1.67:3388)


To:
192.168.1.66(192.168.1.66:3388) (new master)
 +--192.168.1.67(192.168.1.67:3388)
Wed Aug 20 18:31:08 2014 - [info] 
Wed Aug 20 18:31:08 2014 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Wed Aug 20 18:31:08 2014 - [info] 
Wed Aug 20 18:31:08 2014 - [info]  This server has all relay logs. No need to generate diff files from the latest slave.
Wed Aug 20 18:31:08 2014 - [info] Sending binlog..
Wed Aug 20 18:31:09 2014 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog to root@192.168.1.66:/var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog succeeded.
Wed Aug 20 18:31:09 2014 - [info] 
Wed Aug 20 18:31:09 2014 - [info] * Phase 3.4: Master Log Apply Phase..
Wed Aug 20 18:31:09 2014 - [info] 
Wed Aug 20 18:31:09 2014 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Wed Aug 20 18:31:09 2014 - [info] Starting recovery on 192.168.1.66(192.168.1.66:3388)..
Wed Aug 20 18:31:09 2014 - [info]  Generating diffs succeeded.
Wed Aug 20 18:31:09 2014 - [info] Waiting until all relay logs are applied.
Wed Aug 20 18:31:09 2014 - [info]  done.
Wed Aug 20 18:31:09 2014 - [info] Getting slave status..
Wed Aug 20 18:31:09 2014 - [info] This slave(192.168.1.66)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000018:3330). No need to recover from Exec_Master_Log_Pos.
Wed Aug 20 18:31:09 2014 - [info] Connecting to the target slave host 192.168.1.66, running recover script..
Wed Aug 20 18:31:09 2014 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='root' --slave_host=192.168.1.66 --slave_ip=192.168.1.66  --slave_port=3388 --apply_files=/var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog --workdir=/var/tmp --target_version=5.6.10-log --timestamp=20140820183106 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx
Wed Aug 20 18:31:09 2014 - [info] 
MySQL client version is 5.6.10. Using --binary-mode.
Applying differential binary/relay log files /var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog on 192.168.1.66:3388. This may take long time...
Applying log files succeeded.
Wed Aug 20 18:31:09 2014 - [info]  All relay logs were successfully applied.
Wed Aug 20 18:31:09 2014 - [info] Getting new master's binlog name and position..
Wed Aug 20 18:31:09 2014 - [info]  mysql-bin.000020:1736
Wed Aug 20 18:31:09 2014 - [info]  All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.1.66', MASTER_PORT=3388, MASTER_LOG_FILE='mysql-bin.000020', MASTER_LOG_POS=1736, MASTER_USER='repuser', MASTER_PASSWORD='xxx';
Wed Aug 20 18:31:09 2014 - [warning] master_ip_failover_script is not set. Skipping taking over new master IP address.
Wed Aug 20 18:31:09 2014 - [info] ** Finished master recovery successfully.
Wed Aug 20 18:31:09 2014 - [info] * Phase 3: Master Recovery Phase completed.
Wed Aug 20 18:31:09 2014 - [info] 
Wed Aug 20 18:31:09 2014 - [info] * Phase 4: Slaves Recovery Phase..
Wed Aug 20 18:31:09 2014 - [info] 
Wed Aug 20 18:31:09 2014 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Wed Aug 20 18:31:09 2014 - [info] 
Wed Aug 20 18:31:09 2014 - [info] -- Slave diff file generation on host 192.168.1.67(192.168.1.67:3388) started, pid: 4590. Check tmp log /masterha/app1/192.168.1.67_3388_20140820183106.log if it takes time..
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:10 2014 - [info] Log messages from 192.168.1.67 ...
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:09 2014 - [info] Server 192.168.1.67 received relay logs up to: mysql-bin.000018:120
Wed Aug 20 18:31:09 2014 - [info] Need to get diffs from the latest slave(192.168.1.66) up to: mysql-bin.000018:3330 (using the latest slave's relay logs)
Wed Aug 20 18:31:09 2014 - [info] Connecting to the latest slave host 192.168.1.66, generating diff relay log files..
Wed Aug 20 18:31:09 2014 - [info] Executing command: apply_diff_relay_logs --command=generate_and_send --scp_user=root --scp_host=192.168.1.67 --latest_mlf=mysql-bin.000018 --latest_rmlp=3330 --target_mlf=mysql-bin.000018 --target_rmlp=120 --server_id=2 --diff_file_readtolatest=/var/tmp/relay_from_read_to_latest_192.168.1.67_3388_20140820183106.binlog --workdir=/var/tmp --timestamp=20140820183106 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/mysql/data/mysql5610/data/relay-log.info  --relay_dir=/mysql/data/mysql5610/data/ 
Wed Aug 20 18:31:10 2014 - [info] 
    Opening /mysql/data/mysql5610/data/relay-log.info ... ok.
    Relay log found at /mysql/data/mysql5610/data, up to localhost-relay-bin.000002
 Fast relay log position search succeeded.
 Target relay log file/position found. start_file:localhost-relay-bin.000002, start_pos:283.
 Concat binary/relay logs from localhost-relay-bin.000002 pos 283 to localhost-relay-bin.000002 EOF into /var/tmp/relay_from_read_to_latest_192.168.1.67_3388_20140820183106.binlog ..
  Dumping binlog format description event, from position 0 to 283.. ok.
  Dumping effective binlog data from /mysql/data/mysql5610/data/localhost-relay-bin.000002 position 283 to tail(3493).. ok.
 Concat succeeded.
 Generating diff relay log succeeded. Saved at /var/tmp/relay_from_read_to_latest_192.168.1.67_3388_20140820183106.binlog .
 scp localhost.localdomain:/var/tmp/relay_from_read_to_latest_192.168.1.67_3388_20140820183106.binlog to root@192.168.1.67(22) succeeded.
Wed Aug 20 18:31:10 2014 - [info]  Generating diff files succeeded.
Wed Aug 20 18:31:10 2014 - [info] End of log messages from 192.168.1.67.
Wed Aug 20 18:31:10 2014 - [info] -- Slave diff log generation on host 192.168.1.67(192.168.1.67:3388) succeeded.
Wed Aug 20 18:31:10 2014 - [info] Generating relay diff files from the latest slave succeeded.
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:10 2014 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:10 2014 - [info] -- Slave recovery on host 192.168.1.67(192.168.1.67:3388) started, pid: 4597. Check tmp log /masterha/app1/192.168.1.67_3388_20140820183106.log if it takes time..
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:10 2014 - [info] Log messages from 192.168.1.67 ...
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:10 2014 - [info] Sending binlog..
Wed Aug 20 18:31:10 2014 - [info] scp from local:/masterha/app1/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog to root@192.168.1.67:/var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog succeeded.
Wed Aug 20 18:31:10 2014 - [info] Starting recovery on 192.168.1.67(192.168.1.67:3388)..
Wed Aug 20 18:31:10 2014 - [info]  Generating diffs succeeded.
Wed Aug 20 18:31:10 2014 - [info] Waiting until all relay logs are applied.
Wed Aug 20 18:31:10 2014 - [info]  done.
Wed Aug 20 18:31:10 2014 - [info] Getting slave status..
Wed Aug 20 18:31:10 2014 - [info] This slave(192.168.1.67)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000018:120). No need to recover from Exec_Master_Log_Pos.
Wed Aug 20 18:31:10 2014 - [info] Connecting to the target slave host 192.168.1.67, running recover script..
Wed Aug 20 18:31:10 2014 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='root' --slave_host=192.168.1.67 --slave_ip=192.168.1.67  --slave_port=3388 --apply_files=/var/tmp/relay_from_read_to_latest_192.168.1.67_3388_20140820183106.binlog,/var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog --workdir=/var/tmp --target_version=5.6.10-log --timestamp=20140820183106 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx
Wed Aug 20 18:31:10 2014 - [info] 
 Concat all apply files to /var/tmp/total_binlog_for_192.168.1.67_3388.20140820183106.binlog ..
 Copying the first binlog file /var/tmp/relay_from_read_to_latest_192.168.1.67_3388_20140820183106.binlog to /var/tmp/total_binlog_for_192.168.1.67_3388.20140820183106.binlog.. ok.
  Dumping binlog head events (rotate events), skipping format description events from /var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog.. dumped up to pos 120. ok.
 /var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog has effective binlog events from pos 120.
  Dumping effective binlog data from /var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog position 120 to tail(1855).. ok.
 Concat succeeded.
All apply target binary logs are concatinated at /var/tmp/total_binlog_for_192.168.1.67_3388.20140820183106.binlog .
MySQL client version is 5.6.10. Using --binary-mode.
Applying differential binary/relay log files /var/tmp/relay_from_read_to_latest_192.168.1.67_3388_20140820183106.binlog,/var/tmp/saved_master_binlog_from_192.168.1.65_3388_20140820183106.binlog on 192.168.1.67:3388. This may take long time...
Applying log files succeeded.
Wed Aug 20 18:31:10 2014 - [info]  All relay logs were successfully applied.
Wed Aug 20 18:31:10 2014 - [info]  Resetting slave 192.168.1.67(192.168.1.67:3388) and starting replication from the new master 192.168.1.66(192.168.1.66:3388)..
Wed Aug 20 18:31:10 2014 - [info]  Executed CHANGE MASTER.
Wed Aug 20 18:31:10 2014 - [info]  Slave started.
Wed Aug 20 18:31:10 2014 - [info] End of log messages from 192.168.1.67.
Wed Aug 20 18:31:10 2014 - [info] -- Slave recovery on host 192.168.1.67(192.168.1.67:3388) succeeded.
Wed Aug 20 18:31:10 2014 - [info] All new slave servers recovered successfully.
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:10 2014 - [info] * Phase 5: New master cleanup phase..
Wed Aug 20 18:31:10 2014 - [info] 
Wed Aug 20 18:31:10 2014 - [info] Resetting slave info on the new master..
Wed Aug 20 18:31:10 2014 - [info]  192.168.1.66: Resetting slave info succeeded.
Wed Aug 20 18:31:10 2014 - [info] Master failover to 192.168.1.66(192.168.1.66:3388) completed successfully.
Wed Aug 20 18:31:10 2014 - [info] 


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


app1: MySQL Master failover 192.168.1.65(192.168.1.65:3388) to 192.168.1.66(192.168.1.66:3388) succeeded


Master 192.168.1.65(192.168.1.65:3388) is down!


Check MHA Manager logs at localhost.localdomain:/masterha/log/manager.log for details.


Started automated(non-interactive) failover.
The latest slave 192.168.1.66(192.168.1.66:3388) has all relay logs for recovery.
Selected 192.168.1.66(192.168.1.66:3388) as a new master.
192.168.1.66(192.168.1.66:3388): OK: Applying all logs succeeded.
192.168.1.67(192.168.1.67:3388): Generating differential relay logs up to 192.168.1.66(192.168.1.66:3388)succeeded.
Generating relay diff files from the latest slave succeeded.
192.168.1.67(192.168.1.67:3388): OK: Applying all logs succeeded. Slave started, replicating from 192.168.1.66(192.168.1.66:3388)
192.168.1.66(192.168.1.66:3388): Resetting slave info succeeded.
Master failover to 192.168.1.66(192.168.1.66:3388) completed successfully.
Wed Aug 20 18:31:10 2014 - [info] Sending mail..
Wed Aug 20 18:31:11 2014 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
Wed Aug 20 18:31:11 2014 - [info] Reading application default configuration from /masterha/conf/app1/app1.cnf..
Wed Aug 20 18:31:11 2014 - [info] Reading server configuration from /masterha/conf/app1/app1.cnf..
Wed Aug 20 18:31:11 2014 - [info] MHA::MasterFailover version 0.56.
----- dhSendReport -----
dead_master_host=192.168.1.65:3388
new_master_host=192.168.1.66:3388
new_slave_hosts=192.168.1.67
subject=app1: MySQL Master failover 192.168.1.65(192.168.1.65:3388) to 192.168.1.66(192.168.1.66:3388) succeeded
body=Master 192.168.1.65(192.168.1.65:3388) is down!


Check MHA Manager logs at localhost.localdomain:/masterha/log/manager.log for details.


Started automated(non-interactive) failover.
The latest slave 192.168.1.66(192.168.1.66:3388) has all relay logs for recovery.
Selected 192.168.1.66(192.168.1.66:3388) as a new master.
192.168.1.66(192.168.1.66:3388): OK: Applying all logs succeeded.
192.168.1.67(192.168.1.67:3388): Generating differential relay logs up to 192.168.1.66(192.168.1.66:3388)succeeded.
Generating relay diff files from the latest slave succeeded.
192.168.1.67(192.168.1.67:3388): OK: Applying all logs succeeded. Slave started, replicating from 192.168.1.66(192.168.1.66:3388)
192.168.1.66(192.168.1.66:3388): Resetting slave info succeeded.
Master failover to 192.168.1.66(192.168.1.66:3388) completed successfully.


command = sh /mysql/script/notify.sh 'phone' 'error' 'Mysql_oldmaster[192.168.1.65:3388]_down_changeto_newmaster[192.168.1.66:3388]' 'Master 192.168.1.65(192.168.1.65:3388) is down!


Check MHA Manager logs at localhost.localdomain:/masterha/log/manager.log for details.


Started automated(non-interactive) failover.
The latest slave 192.168.1.66(192.168.1.66:3388) has all relay logs for recovery.
Selected 192.168.1.66(192.168.1.66:3388) as a new master.
192.168.1.66(192.168.1.66:3388): OK: Applying all logs succeeded.
192.168.1.67(192.168.1.67:3388): Generating differential relay logs up to 192.168.1.66(192.168.1.66:3388)succeeded.
Generating relay diff files from the latest slave succeeded.
192.168.1.67(192.168.1.67:3388): OK: Applying all logs succeeded. Slave started, replicating from 192.168.1.66(192.168.1.66:3388)
192.168.1.66(192.168.1.66:3388): Resetting slave info succeeded.
Master failover to 192.168.1.66(192.168.1.66:3388) completed successfully.
'
Wed Aug 20 18:31:11 2014 - [info] 
type: phone
warnlv: error
subject: Mysql_oldmaster[192.168.1.65:3388]_down_changeto_newmaster[192.168.1.66:3388]
context: Master 192.168.1.65(192.168.1.65:3388) is down!


Check MHA Manager logs at localhost.localdomain:/masterha/log/manager.log for details.


Started automated(non-interactive) failover.
The latest slave 192.168.1.66(192.168.1.66:3388) has all relay logs for recovery.
Selected 192.168.1.66(192.168.1.66:3388) as a new master.
192.168.1.66(192.168.1.66:3388): OK: Applying all logs succeeded.
192.168.1.67(192.168.1.67:3388): Generating differential relay logs up to 192.168.1.66(192.168.1.66:3388)succeeded.
Generating relay diff files from the latest slave succeeded.
192.168.1.67(192.168.1.67:3388): OK: Applying all logs succeeded. Slave started, replicating from 192.168.1.66(192.168.1.66:3388)
192.168.1.66(192.168.1.66:3388): Resetting slave info succeeded.
Master failover to 192.168.1.66(192.168.1.66:3388) completed successfully.


--2014-08-20 18:31:11--  http://124.42.15.208/message.php?phone=13511075902,13910814332,13581667201,13521023786&msg=Mysql_oldmaster[192.168.1.65:3388]_down_changeto_newmaster[192.168.1.66:3388]%2018:31:11
Connecting to 124.42.15.208:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/html]
Saving to: “/dev/null”


     0K ......                                                 8.68M=0.001s


2014-08-20 18:31:39 (8.68 MB/s) - “/dev/null” saved [7088]


--2014-08-20 18:31:39--  http://124.42.15.208/message.php?item=mail&mailto=dba.list@dhgate.com&subject=Mysql_oldmaster[192.168.1.65:3388]_down_changeto_newmaster[192.168.1.66:3388]&msg=Master%20192.168.1.65(192.168.1.65:3388)%20is%20down!%0A%0ACheck%20MHA%20Manager%20logs%20at%20localhost.localdomain:/masterha/log/manager.log%20for%20details.%0A%0AStarted%20automated(non-interactive)%20failover.%0AThe%20latest%20slave%20192.168.1.66(192.168.1.66:3388)%20has%20all%20relay%20logs%20for%20recovery.%0ASelected%20192.168.1.66(192.168.1.66:3388)%20as%20a%20new%20master.%0A192.168.1.66(192.168.1.66:3388):%20OK:%20Applying%20all%20logs%20succeeded.%0A192.168.1.67(192.168.1.67:3388):%20Generating%20differential%20relay%20logs%20up%20to%20192.168.1.66(192.168.1.66:3388)succeeded.%0AGenerating%20relay%20diff%20files%20from%20the%20latest%20slave%20succeeded.%0A192.168.1.67(192.168.1.67:3388):%20OK:%20Applying%20all%20logs%20succeeded.%20Slave%20started,%20replicating%20from%20192.168.1.66(192.168.1.66:3388)%0A192.168.1.66(192.168.1.66:3388):%20Resetting%20slave%20info%20succeeded.%0AMaster%20failover%20to%20192.168.1.66(192.168.1.66:3388)%20completed%20successfully.%0A%2018:31:11
Connecting to 124.42.15.208:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/html]
Saving to: “/dev/null”


     0K .                                                       141M=0s


2014-08-20 18:32:17 (141 MB/s) - “/dev/null” saved [1874]


 done.