mha 与 mysql cluster_MySQL高可用篇之MHA集群

Sun May 24 18:35:56 2020 - [warning] Got error on MySQL select ping: 2006(MySQL server has gone away)

Sun May24 18:35:56 2020 - [info] Executing SSH check script: save_binary_logs --command=test --start_pos=4 --binlog_dir=/data/mysql3306/data --output_file=/tmp/save_binary_logs_test --manager_version=0.58 --binlog_prefix=mysql-bin

Sun May 24 18:35:56 2020 - [info] HealthCheck: SSH to 192.168.28.128 isreachable.

Sun May24 18:35:59 2020 - [warning] Got error on MySQL connect: 2003 (Can't connect to MySQL server on'192.168.28.128'(111))

Sun May 24 18:35:59 2020 - [warning] Connection failed 2 time(s)..

Sun May 24 18:36:02 2020 - [warning] Got error on MySQL connect: 2003 (Can't connect to MySQL server on '192.168.28.128' (111))

Sun May24 18:36:02 2020 - [warning] Connection failed 3time(s)..

Sun May24 18:36:05 2020 - [warning] Got error on MySQL connect: 2003 (Can't connect to MySQL server on'192.168.28.128'(111))

Sun May 24 18:36:05 2020 - [warning] Connection failed 4 time(s)..

Sun May 24 18:36:05 2020 - [warning] Master is not reachable from health checker!

Sun May 24 18:36:05 2020 - [warning] Master 192.168.28.128(192.168.28.128:3306) is not reachable!

Sun May 24 18:36:05 2020 - [warning] SSH is reachable.

Sun May 24 18:36:05 2020 - [info] Connecting to a master server failed. Reading configuration file /etc/masterha_default.cnf and /etc/masterha/app1.conf again, and trying to connect to all servers to check server status..

Sun May 24 18:36:05 2020 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.

Sun May 24 18:36:05 2020 - [info] Reading application default configuration from /etc/masterha/app1.conf..

Sun May 24 18:36:05 2020 - [info] Reading server configuration from /etc/masterha/app1.conf..

Sun May 24 18:36:06 2020 - [info] GTID failover mode = 0

Sun May 24 18:36:06 2020 - [info] Dead Servers:

Sun May 24 18:36:06 2020 - [info] 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:06 2020 - [info] Alive Servers:

Sun May 24 18:36:06 2020 - [info] 192.168.28.131(192.168.28.131:3306)

Sun May 24 18:36:06 2020 - [info] 192.168.28.132(192.168.28.132:3306)

Sun May 24 18:36:06 2020 - [info] Alive Slaves:

Sun May 24 18:36:06 2020 - [info] 192.168.28.131(192.168.28.131:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:06 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:06 2020 - [info] Primary candidate for the new Master (candidate_master is set)

Sun May 24 18:36:06 2020 - [info] 192.168.28.132(192.168.28.132:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:06 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:06 2020 - [info] Not candidate for the new Master (no_master is set)

Sun May 24 18:36:06 2020 - [info] Checking slave configurations..

Sun May 24 18:36:06 2020 - [info] Checking replication filtering settings..

Sun May 24 18:36:06 2020 - [info] Replication filtering check ok.

Sun May 24 18:36:06 2020 - [info] Master is down!

Sun May 24 18:36:06 2020 - [info] Terminating monitoring script.

Sun May 24 18:36:06 2020 - [info] Got exit code 20 (Master dead).

Sun May 24 18:36:06 2020 - [info] MHA::MasterFailover version 0.58.

Sun May 24 18:36:06 2020 - [info] Starting master failover.

Sun May 24 18:36:06 2020 - [info]

Sun May 24 18:36:06 2020 - [info] * Phase 1: Configuration Check Phase..

Sun May 24 18:36:06 2020 - [info]

Sun May 24 18:36:07 2020 - [info] GTID failover mode = 0

Sun May 24 18:36:07 2020 - [info] Dead Servers:

Sun May 24 18:36:07 2020 - [info] 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:07 2020 - [info] Checking master reachability via MySQL(double check)...

Sun May 24 18:36:07 2020 - [info] ok.

Sun May 24 18:36:07 2020 - [info] Alive Servers:

Sun May 24 18:36:07 2020 - [info] 192.168.28.131(192.168.28.131:3306)

Sun May 24 18:36:07 2020 - [info] 192.168.28.132(192.168.28.132:3306)

Sun May 24 18:36:07 2020 - [info] Alive Slaves:

Sun May 24 18:36:07 2020 - [info] 192.168.28.131(192.168.28.131:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:07 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:07 2020 - [info] Primary candidate for the new Master (candidate_master is set)

Sun May 24 18:36:07 2020 - [info] 192.168.28.132(192.168.28.132:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:07 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:07 2020 - [info] Not candidate for the new Master (no_master is set)

Sun May 24 18:36:07 2020 - [info] Starting Non-GTID based failover.

Sun May 24 18:36:07 2020 - [info]

Sun May 24 18:36:07 2020 - [info] ** Phase 1: Configuration Check Phase completed.

Sun May 24 18:36:07 2020 - [info]

Sun May 24 18:36:07 2020 - [info] * Phase 2: Dead Master Shutdown Phase..

Sun May 24 18:36:07 2020 - [info]

Sun May 24 18:36:07 2020 - [info] * Phase 2: Dead Master Shutdown Phase..

Sun May 24 18:36:07 2020 - [info]

Sun May 24 18:36:07 2020 - [info] Forcing shutdown so that applications never connect to the current master..

Sun May 24 18:36:07 2020 - [info] Executing master IP deactivation script:

Sun May 24 18:36:07 2020 - [info] /usr/bin/master_ip_failover --orig_master_host=192.168.28.128 --orig_master_ip=192.168.28.128 --orig_master_port=3306 --command=stopssh --ssh_user=root

IN SCRIPT TEST====/sbin/ip addr del 192.168.28.199/24 dev ens33==/sbin/ip addr add 192.168.28.199/24 dev ens33===

Disabling the VIP on old master: 192.168.28.128

Sun May 24 18:36:08 2020 - [info] done.

Sun May 24 18:36:08 2020 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.

Sun May 24 18:36:08 2020 - [info] * Phase 2: Dead Master Shutdown Phase completed.

Sun May 24 18:36:08 2020 - [info]

Sun May 24 18:36:08 2020 - [info] * Phase 3: Master Recovery Phase..

Sun May 24 18:36:08 2020 - [info]

Sun May 24 18:36:08 2020 - [info] * Phase 3.1: Getting Latest Slaves Phase..

Sun May 24 18:36:08 2020 - [info]

Sun May 24 18:36:08 2020 - [info] The latest binary log file/position on all slaves is mysql-bin.000013:154

Sun May 24 18:36:08 2020 - [info] Latest slaves (Slaves that received relay log files to the latest):

Sun May 24 18:36:08 2020 - [info] 192.168.28.131(192.168.28.131:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:08 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:08 2020 - [info] Primary candidate for the new Master (candidate_master is set)

Sun May 24 18:36:08 2020 - [info] 192.168.28.132(192.168.28.132:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:08 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:08 2020 - [info] Not candidate for the new Master (no_master is set)

Sun May 24 18:36:08 2020 - [info] The oldest binary log file/position on all slaves is mysql-bin.000013:154

Sun May 24 18:36:08 2020 - [info] Oldest slaves:

Sun May 24 18:36:08 2020 - [info] 192.168.28.131(192.168.28.131:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:08 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:08 2020 - [info] Primary candidate for the new Master (candidate_master is set)

Sun May 24 18:36:08 2020 - [info] 192.168.28.132(192.168.28.132:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:08 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:08 2020 - [info] Not candidate for the new Master (no_master is set)

Sun May 24 18:36:08 2020 - [info]

Sun May 24 18:36:08 2020 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..

Sun May24 18:36:08 2020 - [info]Sun May24 18:36:09 2020 - [info] Fetching dead master's binary logs..

Sun May 24 18:36:09 2020 - [info] Executing command on the dead master 192.168.28.128(192.168.28.128:3306): save_binary_logs --command=save --start_file=mysql-bin.000013 --start_pos=154 --binlog_dir=/data/mysql3306/data --output_file=/tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.58

Creating /tmp if not exists.. ok.

Concat binary/relay logs from mysql-bin.000013 pos 154 to mysql-bin.000013 EOF into /tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog ..

Binlog Checksum enabled

Dumping binlog format description event, from position 0 to 154.. ok.

Dumping effective binlog data from /data/mysql3306/data/mysql-bin.000013 position 154 to tail(177).. ok.

Binlog Checksum enabled

Concat succeeded.

Sun May 24 18:36:11 2020 - [info] scp from root@192.168.28.128:/tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog to local:/var/log/masterha/app1/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog succeeded.

Sun May 24 18:36:12 2020 - [info] HealthCheck: SSH to 192.168.28.131 is reachable.

Sun May 24 18:36:13 2020 - [info] HealthCheck: SSH to 192.168.28.132 is reachable.

Sun May 24 18:36:14 2020 - [info]

Sun May 24 18:36:14 2020 - [info] * Phase 3.3: Determining New Master Phase..

Sun May 24 18:36:14 2020 - [info]

Sun May 24 18:36:14 2020 - [info] Finding the latest slave that has all relay logs for recovering other slaves..

Sun May 24 18:36:14 2020 - [info] All slaves received relay logs to the same position. No need to resync each other.

Sun May 24 18:36:14 2020 - [info] Searching new master from slaves..

Sun May 24 18:36:14 2020 - [info] Candidate masters from the configuration file:

Sun May 24 18:36:14 2020 - [info] 192.168.28.131(192.168.28.131:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:14 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:14 2020 - [info] Primary candidate for the new Master (candidate_master is set)

Sun May 24 18:36:14 2020 - [info] Non-candidate masters:

Sun May 24 18:36:14 2020 - [info] 192.168.28.132(192.168.28.132:3306) Version=5.7.25-28-log (oldest major version between slaves) log-bin:enabled

Sun May 24 18:36:14 2020 - [info] Replicating from 192.168.28.128(192.168.28.128:3306)

Sun May 24 18:36:14 2020 - [info] Not candidate for the new Master (no_master is set)

Sun May 24 18:36:14 2020 - [info] New master is 192.168.28.131(192.168.28.131:3306)

Sun May 24 18:36:14 2020 - [info] Starting master failover..

Sun May 24 18:36:14 2020 - [info]

From:

192.168.28.128(192.168.28.128:3306) (current master)

+--192.168.28.131(192.168.28.131:3306)

+--192.168.28.132(192.168.28.132:3306)

To:

192.168.28.131(192.168.28.131:3306) (new master)

+--192.168.28.132(192.168.28.132:3306)

Sun May 24 18:36:14 2020 - [info]

Sun May 24 18:36:14 2020 - [info] * Phase 3.4: New Master Diff Log Generation Phase..

Sun May 24 18:36:14 2020 - [info]

Sun May 24 18:36:14 2020 - [info] This server has all relay logs. No need to generate diff files from the latest slave.

Sun May 24 18:36:14 2020 - [info] Sending binlog..

Sun May 24 18:36:15 2020 - [info] scp from local:/var/log/masterha/app1/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog to root@192.168.28.131:/tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog succeeded.

Sun May 24 18:36:15 2020 - [info]

Sun May 24 18:36:15 2020 - [info] * Phase 3.5: Master Log Apply Phase..

Sun May 24 18:36:15 2020 - [info]

Sun May 24 18:36:15 2020 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.

Sun May 24 18:36:15 2020 - [info] Starting recovery on 192.168.28.131(192.168.28.131:3306)..

Sun May 24 18:36:15 2020 - [info] Generating diffs succeeded.

Sun May 24 18:36:15 2020 - [info] Waiting until all relay logs are applied.

Sun May 24 18:36:15 2020 - [info] done.

Sun May 24 18:36:15 2020 - [info] Getting slave status..

Sun May 24 18:36:15 2020 - [info] This slave(192.168.28.131)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000013:154). No need to recover fromExec_Master_Log_Pos.

Sun May24 18:36:15 2020 - [info] Connecting to the target slave host 192.168.28.131, running recover script..

Sun May24 18:36:15 2020 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='mha' --slave_host=192.168.28.131 --slave_ip=192.168.28.131 --slave_port=3306 --apply_files=/tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog --workdir=/tmp --target_version=5.7.25-28-log --timestamp=20200524183606 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.58 --slave_pass=xxx

Sun May 24 18:36:16 2020 - [info]MySQL client versionis 5.7.25. Using --binary-mode.

Applying differential binary/relay log files /tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog on 192.168.28.131:3306. This may take longtime...

Applyinglogfiles succeeded.

Sun May24 18:36:16 2020 - [info] Allrelay logs were successfully applied.

Sun May24 18:36:16 2020 - [info] Getting new master's binlog name and position..

Sun May 24 18:36:16 2020 - [info] mysql-bin.000008:154

Sun May 24 18:36:16 2020 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.28.131', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000008', MASTER_LOG_POS=154, MASTER_USER='repl', MASTER_PASSWORD='xxx';

Sun May 24 18:36:16 2020 - [info] Executing master IP activate script:

Sun May 24 18:36:16 2020 - [info] /usr/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.28.128 --orig_master_ip=192.168.28.128 --orig_master_port=3306 --new_master_host=192.168.28.131 --new_master_ip=192.168.28.131 --new_master_port=3306 --new_master_user='mha'--new_master_password=xxx

Unknown option: new_master_user

Unknown option: new_master_password

IN SCRIPT TEST====/sbin/ip addr del 192.168.28.199/24 dev ens33==/sbin/ip addr add 192.168.28.199/24 dev ens33===

Enabling the VIP - 192.168.28.199/24 on the new master - 192.168.28.131

Sun May 24 18:36:17 2020 - [info] OK.

Sun May 24 18:36:17 2020 - [info] Setting read_only=0 on 192.168.28.131(192.168.28.131:3306)..

Sun May 24 18:36:17 2020 - [info] ok.

Sun May 24 18:36:17 2020 - [info] ** Finished master recovery successfully.

Sun May 24 18:36:17 2020 - [info] * Phase 3: Master Recovery Phase completed.

Sun May 24 18:36:17 2020 - [info]

Sun May 24 18:36:17 2020 - [info] * Phase 4: Slaves Recovery Phase..

Sun May 24 18:36:17 2020 - [info]

Sun May 24 18:36:17 2020 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..

Sun May 24 18:36:17 2020 - [info]

Sun May 24 18:36:17 2020 - [info] -- Slave diff file generation on host 192.168.28.132(192.168.28.132:3306) started, pid: 48890. Check tmp log /var/log/masterha/app1/192.168.28.132_3306_20200524183606.log if it takes time..

Sun May 24 18:36:18 2020 - [info]

Sun May 24 18:36:18 2020 - [info]

Sun May 24 18:36:18 2020 - [info] Log messages from 192.168.28.132 ...

Sun May 24 18:36:18 2020 - [info]

Sun May 24 18:36:17 2020 - [info] This server has all relay logs. No need to generate diff files from the latest slave.

Sun May 24 18:36:18 2020 - [info] End of log messages from 192.168.28.132.

Sun May 24 18:36:18 2020 - [info] -- 192.168.28.132(192.168.28.132:3306) has the latest relay log events.

Sun May 24 18:36:18 2020 - [info] Generating relay diff files from the latest slave succeeded.

Sun May 24 18:36:18 2020 - [info]

Sun May 24 18:36:18 2020 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..

Sun May 24 18:36:18 2020 - [info]

Sun May 24 18:36:18 2020 - [info] -- Slave recovery on host 192.168.28.132(192.168.28.132:3306) started, pid: 48892. Check tmp log /var/log/masterha/app1/192.168.28.132_3306_20200524183606.log if it takes time..

Sun May 24 18:36:21 2020 - [info]

Sun May 24 18:36:21 2020 - [info] Log messages from 192.168.28.132 ...

Sun May 24 18:36:21 2020 - [info]

Sun May 24 18:36:18 2020 - [info] Sending binlog..

Sun May 24 18:36:19 2020 - [info] scp from local:/var/log/masterha/app1/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog to root@192.168.28.132:/tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog succeeded.

Sun May 24 18:36:19 2020 - [info] Starting recovery on 192.168.28.132(192.168.28.132:3306)..

Sun May 24 18:36:19 2020 - [info] Generating diffs succeeded.

Sun May 24 18:36:19 2020 - [info] Waiting until all relay logs are applied.

Sun May 24 18:36:19 2020 - [info] done.

Sun May 24 18:36:19 2020 - [info] Getting slave status..

Sun May 24 18:36:19 2020 - [info] This slave(192.168.28.132)'s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000013:154). No need to recover fromExec_Master_Log_Pos.

Sun May24 18:36:19 2020 - [info] Connecting to the target slave host 192.168.28.132, running recover script..

Sun May24 18:36:19 2020 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='mha' --slave_host=192.168.28.132 --slave_ip=192.168.28.132 --slave_port=3306 --apply_files=/tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog --workdir=/tmp --target_version=5.7.25-28-log --timestamp=20200524183606 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.58 --slave_pass=xxx

Sun May 24 18:36:20 2020 - [info]MySQL client versionis 5.7.25. Using --binary-mode.

Applying differential binary/relay log files /tmp/saved_master_binlog_from_192.168.28.128_3306_20200524183606.binlog on 192.168.28.132:3306. This may take longtime...

Applyinglogfiles succeeded.

Sun May24 18:36:20 2020 - [info] Allrelay logs were successfully applied.

Sun May24 18:36:20 2020 - [info] Resetting slave 192.168.28.132(192.168.28.132:3306) and starting replication from the new master 192.168.28.131(192.168.28.131:3306)..

Sun May24 18:36:20 2020 - [info]Executed CHANGE MASTER.

Sun May24 18:36:20 2020 - [info]Slave started.

Sun May24 18:36:21 2020 - [info] End of log messages from 192.168.28.132.

Sun May24 18:36:21 2020 - [info] --Slave recovery on host 192.168.28.132(192.168.28.132:3306) succeeded.

Sun May 24 18:36:21 2020 - [info] Allnew slave servers recovered successfully.

Sun May24 18:36:21 2020 - [info]Sun May24 18:36:21 2020 - [info] * Phase 5: New master cleanup phase..

Sun May24 18:36:21 2020 - [info]Sun May24 18:36:21 2020 - [info] Resetting slave info onthe new master..

Sun May24 18:36:21 2020 - [info] 192.168.28.131: Resetting slave info succeeded.

Sun May24 18:36:21 2020 - [info] Master failover to 192.168.28.131(192.168.28.131:3306) completed successfully.

Sun May24 18:36:21 2020 - [info]

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

app1: MySQL Master failover192.168.28.128(192.168.28.128:3306) to 192.168.28.131(192.168.28.131:3306) succeeded

Master192.168.28.128(192.168.28.128:3306) isdown!Check MHA Manager logs at mha3:/var/log/masterha/app1/app1.log fordetails.

Started automated(non-interactive) failover.

Invalidated master IP addresson 192.168.28.128(192.168.28.128:3306)

The latest slave192.168.28.131(192.168.28.131:3306) has all relay logs forrecovery.

Selected192.168.28.131(192.168.28.131:3306) asa new master.192.168.28.131(192.168.28.131:3306): OK: Applying alllogs succeeded.192.168.28.131(192.168.28.131:3306): OK: Activated master IP address.192.168.28.132(192.168.28.132:3306): This host has the latest relay logevents.

Generating relay diff filesfromthe latest slave succeeded.192.168.28.132(192.168.28.132:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.28.131(192.168.28.131:3306)192.168.28.131(192.168.28.131:3306): Resetting slave info succeeded.

Master failoverto 192.168.28.131(192.168.28.131:3306) completed successfully.