Thu Jul 28 17:10:25 2016 - [info] MHA::MasterMonitor version 0.56.
Thu Jul 28 17:10:26 2016 - [info] GTID failover mode = 0
Thu Jul 28 17:10:26 2016 - [info] Dead Servers:
Thu Jul 28 17:10:26 2016 - [info] Alive Servers:
Thu Jul 28 17:10:26 2016 - [info] host_1(host_1:3306)
Thu Jul 28 17:10:26 2016 - [info] host_2(host_2:3306)
Thu Jul 28 17:10:26 2016 - [info] host_3(host_3:3306)
Thu Jul 28 17:10:26 2016 - [info] Alive Slaves:
Thu Jul 28 17:10:26 2016 - [info] host_2(host_2:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:10:26 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:10:26 2016 - [info] Primary candidate for the new Master (candidate_master is set)
Thu Jul 28 17:10:26 2016 - [info] host_3(host_3:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:10:26 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:10:26 2016 - [info] Not candidate for the new Master (no_master is set)
Thu Jul 28 17:10:26 2016 - [info] Current Alive Master: host_1(host_1:3306)
Thu Jul 28 17:10:26 2016 - [info] Checking slave configurations..
Thu Jul 28 17:10:26 2016 - [info] read_only=1 is not set on slave host_2(host_2:3306).
Thu Jul 28 17:10:26 2016 - [warning] relay_log_purge=0 is not set on slave host_3(host_3:3306).
Thu Jul 28 17:10:26 2016 - [info] Checking replication filtering settings..
Thu Jul 28 17:10:26 2016 - [info] binlog_do_db= , binlog_ignore_db=
Thu Jul 28 17:10:26 2016 - [info] Replication filtering check ok.
Thu Jul 28 17:10:26 2016 - [info] GTID (with auto-pos) is not supported
Thu Jul 28 17:10:26 2016 - [info] Starting SSH connection tests..
Thu Jul 28 17:10:27 2016 - [info] All SSH connection tests passed successfully.
Thu Jul 28 17:10:27 2016 - [info] Checking MHA Node version..
Thu Jul 28 17:10:28 2016 - [info] Version check ok.
Thu Jul 28 17:10:28 2016 - [info] Checking SSH publickey authentication settings on the current master..
Thu Jul 28 17:10:28 2016 - [info] HealthCheck: SSH to host_1 is reachable.
Thu Jul 28 17:10:29 2016 - [info] Master MHA Node version is 0.56.
Thu Jul 28 17:10:29 2016 - [info] Checking recovery script configurations on host_1(host_1:3306)..
Thu Jul 28 17:10:29 2016 - [info] Executing command: save_binary_logs
Thu Jul 28 17:10:29 2016 - [info] Connecting to root@host_1(host_1:22)..
Creating /var/log/masterha/app1 if not exists.. ok.
Checking output directory is accessible or not..
ok.
Binlog found at /data/mysql.bin, up to host_1_name.000004
Thu Jul 28 17:10:29 2016 - [info] Binlog setting check done.
Thu Jul 28 17:10:29 2016 - [info] Checking SSH publickey authentication and checking recovery script configurations on all alive slave servers..
Thu Jul 28 17:10:29 2016 - [info] Executing command : apply_diff_relay_logs
Thu Jul 28 17:10:29 2016 - [info] Connecting to root@host_2(host_2:22)..
Checking slave recovery environment settings..
Relay log found at /data/mysql_data, up to host_2_name-relay-bin.000002
Temporary relay log file is /data/mysql_data/host_2_name-relay-bin.000002
Testing mysql connection and privileges..mysql: [Warning] Using a password on the command line interface can be insecure.
done.
Testing mysqlbinlog output.. done.
Cleaning up test file(s).. done.
Thu Jul 28 17:10:29 2016 - [info] Executing command : apply_diff_relay_logs
Thu Jul 28 17:10:29 2016 - [info] Connecting to root@host_3(host_3:22)..
Checking slave recovery environment settings..
Relay log found at /data/mysql_data, up to host_3_name-relay-bin.000002
Temporary relay log file is /data/mysql_data/host_3_name-relay-bin.000002
Testing mysql connection and privileges..mysql: [Warning] Using a password on the command line interface can be insecure.
done.
Testing mysqlbinlog output.. done.
Cleaning up test file(s).. done.
Thu Jul 28 17:10:29 2016 - [info] Slaves settings check done.
Thu Jul 28 17:10:29 2016 - [info]
host_1(host_1:3306) (current master)
+
+
Thu Jul 28 17:10:29 2016 - [info] Checking master_ip_failover_script status:
Thu Jul 28 17:10:29 2016 - [info] /home/mysql/MHA/masterha/master_ip_failover
Thu Jul 28 17:10:30 2016 - [info] OK.
Thu Jul 28 17:10:30 2016 - [warning] shutdown_script is not defined.
Thu Jul 28 17:10:30 2016 - [info] Set master ping interval 3 seconds.
Thu Jul 28 17:10:30 2016 - [warning] secondary_check_script is not defined. It is highly recommended setting it to check master reachability from two or more routes.
Thu Jul 28 17:10:30 2016 - [info] Starting ping health check on host_1(host_1:3306)..
Thu Jul 28 17:10:30 2016 - [info] Ping(SELECT) succeeded, waiting until MySQL doesn't respond..
Thu Jul 28 17:11:21 2016 - [warning] Got error on MySQL select ping: 2006 (MySQL server has gone away)
Thu Jul 28 17:11:21 2016 - [info] Executing SSH check script: save_binary_logs
Thu Jul 28 17:11:21 2016 - [info] HealthCheck: SSH to host_1 is reachable.
Thu Jul 28 17:11:24 2016 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Thu Jul 28 17:11:24 2016 - [warning] Connection failed 2 time(s)..
Thu Jul 28 17:11:27 2016 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Thu Jul 28 17:11:27 2016 - [warning] Connection failed 3 time(s)..
Thu Jul 28 17:11:30 2016 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
Thu Jul 28 17:11:30 2016 - [warning] Connection failed 4 time(s)..
Thu Jul 28 17:11:30 2016 - [warning] Master is not reachable from health checker!
Thu Jul 28 17:11:30 2016 - [warning] Master host_1(host_1:3306) is not reachable!
Thu Jul 28 17:11:30 2016 - [warning] SSH is reachable.
Thu Jul 28 17:11:30 2016 - [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..
Thu Jul 28 17:11:30 2016 - [info] Reading default configuration from /etc/masterha_default.cnf..
Thu Jul 28 17:11:30 2016 - [info] Reading application default configuration from /etc/app1.cnf..
Thu Jul 28 17:11:30 2016 - [info] Reading server configuration from /etc/app1.cnf..
Thu Jul 28 17:11:30 2016 - [info] GTID failover mode = 0
Thu Jul 28 17:11:30 2016 - [info] Dead Servers:
Thu Jul 28 17:11:30 2016 - [info] host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Alive Servers:
Thu Jul 28 17:11:30 2016 - [info] host_2(host_2:3306)
Thu Jul 28 17:11:30 2016 - [info] host_3(host_3:3306)
Thu Jul 28 17:11:30 2016 - [info] Alive Slaves:
Thu Jul 28 17:11:30 2016 - [info] host_2(host_2:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Primary candidate for the new Master (candidate_master is set)
Thu Jul 28 17:11:30 2016 - [info] host_3(host_3:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Not candidate for the new Master (no_master is set)
Thu Jul 28 17:11:30 2016 - [info] Checking slave configurations..
Thu Jul 28 17:11:30 2016 - [info] read_only=1 is not set on slave host_2(host_2:3306).
Thu Jul 28 17:11:30 2016 - [warning] relay_log_purge=0 is not set on slave host_3(host_3:3306).
Thu Jul 28 17:11:30 2016 - [info] Checking replication filtering settings..
Thu Jul 28 17:11:30 2016 - [info] Replication filtering check ok.
Thu Jul 28 17:11:30 2016 - [info] Master is down!
Thu Jul 28 17:11:30 2016 - [info] Terminating monitoring script.
Thu Jul 28 17:11:30 2016 - [info] Got exit code 20 (Master dead).
Thu Jul 28 17:11:30 2016 - [info] MHA::MasterFailover version 0.56.
Thu Jul 28 17:11:30 2016 - [info] Starting master failover.
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] * Phase 1: Configuration Check Phase..
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] GTID failover mode = 0
Thu Jul 28 17:11:30 2016 - [info] Dead Servers:
Thu Jul 28 17:11:30 2016 - [info] host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Checking master reachability via MySQL(double check)...
Thu Jul 28 17:11:30 2016 - [info] ok.
Thu Jul 28 17:11:30 2016 - [info] Alive Servers:
Thu Jul 28 17:11:30 2016 - [info] host_2(host_2:3306)
Thu Jul 28 17:11:30 2016 - [info] host_3(host_3:3306)
Thu Jul 28 17:11:30 2016 - [info] Alive Slaves:
Thu Jul 28 17:11:30 2016 - [info] host_2(host_2:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Primary candidate for the new Master (candidate_master is set)
Thu Jul 28 17:11:30 2016 - [info] host_3(host_3:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Not candidate for the new Master (no_master is set)
Thu Jul 28 17:11:30 2016 - [info] Starting Non-GTID based failover.
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] ** Phase 1: Configuration Check Phase completed.
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] * Phase 2: Dead Master Shutdown Phase..
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] Forcing shutdown so that applications never connect to the current master..
Thu Jul 28 17:11:30 2016 - [info] Executing master IP deactivation script:
Thu Jul 28 17:11:30 2016 - [info] /home/mysql/MHA/masterha/master_ip_failover
Thu Jul 28 17:11:30 2016 - [info] done.
Thu Jul 28 17:11:30 2016 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
Thu Jul 28 17:11:30 2016 - [info] * Phase 2: Dead Master Shutdown Phase completed.
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] * Phase 3: Master Recovery Phase..
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] * Phase 3.1: Getting Latest Slaves Phase..
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] The latest binary log file/position on all slaves is host_1_name.000004:154
Thu Jul 28 17:11:30 2016 - [info] Latest slaves (Slaves that received relay log files to the latest):
Thu Jul 28 17:11:30 2016 - [info] host_2(host_2:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Primary candidate for the new Master (candidate_master is set)
Thu Jul 28 17:11:30 2016 - [info] host_3(host_3:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Not candidate for the new Master (no_master is set)
Thu Jul 28 17:11:30 2016 - [info] The oldest binary log file/position on all slaves is host_1_name.000004:154
Thu Jul 28 17:11:30 2016 - [info] Oldest slaves:
Thu Jul 28 17:11:30 2016 - [info] host_2(host_2:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Primary candidate for the new Master (candidate_master is set)
Thu Jul 28 17:11:30 2016 - [info] host_3(host_3:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:30 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:30 2016 - [info] Not candidate for the new Master (no_master is set)
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..
Thu Jul 28 17:11:30 2016 - [info]
Thu Jul 28 17:11:30 2016 - [info] Fetching dead master's binary logs..
Thu Jul 28 17:11:30 2016 - [info] Executing command on the dead master host_1(host_1:3306): save_binary_logs
Creating /var/log/masterha/app1 if not exists.. ok.
Concat binary/relay logs from host_1_name.000004 pos 154 to host_1_name.000004 EOF into /var/log/masterha/app1/saved_master_binlog_from_host_1_3306_20160728171130.binlog ..
Binlog Checksum enabled
Dumping binlog format description event, from position 0 to 154.. ok.
No need to dump effective binlog data from /data/mysql.bin/host_1_name.000004 (pos starts 154, filesize 154). Skipping.
Binlog Checksum enabled
/var/log/masterha/app1/saved_master_binlog_from_host_1_3306_20160728171130.binlog has no effective data events.
Event not exists.
Thu Jul 28 17:11:31 2016 - [info] Additional events were not found from the orig master. No need to save.
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] * Phase 3.3: Determining New Master Phase..
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Thu Jul 28 17:11:31 2016 - [info] All slaves received relay logs to the same position. No need to resync each other.
Thu Jul 28 17:11:31 2016 - [info] Searching new master from slaves..
Thu Jul 28 17:11:31 2016 - [info] Candidate masters from the configuration file:
Thu Jul 28 17:11:31 2016 - [info] host_2(host_2:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:31 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:31 2016 - [info] Primary candidate for the new Master (candidate_master is set)
Thu Jul 28 17:11:31 2016 - [info] Non-candidate masters:
Thu Jul 28 17:11:31 2016 - [info] host_3(host_3:3306) Version=5.7.13-log (oldest major version between slaves) log-bin:enabled
Thu Jul 28 17:11:31 2016 - [info] Replicating from host_1(host_1:3306)
Thu Jul 28 17:11:31 2016 - [info] Not candidate for the new Master (no_master is set)
Thu Jul 28 17:11:31 2016 - [info] Searching from candidate_master slaves which have received the latest relay log events..
Thu Jul 28 17:11:31 2016 - [info] New master is host_2(host_2:3306)
Thu Jul 28 17:11:31 2016 - [info] Starting master failover..
Thu Jul 28 17:11:31 2016 - [info]
From:
host_1(host_1:3306) (current master)
+
+
To:
host_2(host_2:3306) (new master)
+
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] * Phase 3.4: Master Log Apply Phase..
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Thu Jul 28 17:11:31 2016 - [info] Starting recovery on host_2(host_2:3306)..
Thu Jul 28 17:11:31 2016 - [info] This server has all relay logs. Waiting all logs to be applied..
Thu Jul 28 17:11:31 2016 - [info] done.
Thu Jul 28 17:11:31 2016 - [info] All relay logs were successfully applied.
Thu Jul 28 17:11:31 2016 - [info] Getting new master's binlog name and position..
Thu Jul 28 17:11:31 2016 - [info] host_2_name.000002:294
Thu Jul 28 17:11:31 2016 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='host_2', MASTER_PORT=3306, MASTER_LOG_FILE='host_2_name.000002', MASTER_LOG_POS=294, MASTER_USER='repl', MASTER_PASSWORD='xxx';
Thu Jul 28 17:11:31 2016 - [info] Executing master IP activate script:
Thu Jul 28 17:11:31 2016 - [info] /home/mysql/MHA/masterha/master_ip_failover
Set read_only=0 on the new master.
No need to Creating app user on the new master..
Thu Jul 28 17:11:31 2016 - [info] OK.
Thu Jul 28 17:11:31 2016 - [info] ** Finished master recovery successfully.
Thu Jul 28 17:11:31 2016 - [info] * Phase 3: Master Recovery Phase completed.
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] * Phase 4: Slaves Recovery Phase..
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] Log messages from host_3 ...
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] This server has all relay logs. No need to generate diff files from the latest slave.
Thu Jul 28 17:11:31 2016 - [info] End of log messages from host_3.
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] Generating relay diff files from the latest slave succeeded.
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] Log messages from host_3 ...
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] Starting recovery on host_3(host_3:3306)..
Thu Jul 28 17:11:31 2016 - [info] This server has all relay logs. Waiting all logs to be applied..
Thu Jul 28 17:11:31 2016 - [info] done.
Thu Jul 28 17:11:31 2016 - [info] All relay logs were successfully applied.
Thu Jul 28 17:11:31 2016 - [info] Resetting slave host_3(host_3:3306) and starting replication from the new master host_2(host_2:3306)..
Thu Jul 28 17:11:31 2016 - [info] Executed CHANGE MASTER.
Thu Jul 28 17:11:31 2016 - [info] Slave started.
Thu Jul 28 17:11:31 2016 - [info] End of log messages from host_3.
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] All new slave servers recovered successfully.
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] * Phase 5: New master cleanup phase..
Thu Jul 28 17:11:31 2016 - [info]
Thu Jul 28 17:11:31 2016 - [info] Resetting slave info on the new master..
Thu Jul 28 17:11:31 2016 - [info] host_2: Resetting slave info succeeded.
Thu Jul 28 17:11:31 2016 - [info] Master failover to host_2(host_2:3306) completed successfully.
Thu Jul 28 17:11:31 2016 - [info]
app1: MySQL Master failover host_1(host_1:3306) to host_2(host_2:3306) succeeded
Master host_1(host_1:3306) is down!
Check MHA Manager logs at host_manager_name:/var/log/masterha/app1/app1.log for details.
Started automated(non-interactive) failover.
Invalidated master IP address on host_1(host_1:3306)
The latest slave host_2(host_2:3306) has all relay logs for recovery.
Selected host_2(host_2:3306) as a new master.
host_2(host_2:3306): OK: Applying all logs succeeded.
host_2(host_2:3306): OK: Activated master IP address.
host_3(host_3:3306): This host has the latest relay log events.
Generating relay diff files from the latest slave succeeded.
host_3(host_3:3306): OK: Applying all logs succeeded. Slave started, replicating from host_2(host_2:3306)
host_2(host_2:3306): Resetting slave info succeeded.
Master failover to host_2(host_2:3306) completed successfully.