error 3613 mysql,MySQL高可用方案MHA自动Failover与手动Failover的实践及原理

Sun May 21 09:46:56 2017 - [warning] Got error on MySQL select ping: 2006(MySQL server has gone away)

Sun May21 09:46:56 2017 - [info] Executing secondary network check script: /usr/local/bin/masterha_secondary_check -s 192.168.244.20 -s 192.168.244.30 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --user=root --master_host=192.168.244.10 --master_ip=192.168.244.10 --master_port=3306 --master_user=monitor --masteConnection timed out during banner exchange

Sun May21 09:47:08 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.

Sun May21 09:47:08 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..

Sun May21 09:47:08 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..

to MySQL server at'reading initial communication packet', system error: 111)

Sun May21 09:46:57 2017 - [warning] Connection failed 2 time(s)..

Sun May21 09:46:58 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)

Sun May21 09:46:58 2017 - [warning] Connection failed 3 time(s)..

Sun May21 09:46:59 2017 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)

Sun May21 09:46:59 2017 - [warning] Connection failed 4 time(s)..

Monitoring server192.168.244.20 is reachable, Master is not reachable from 192.168.244.20. OK.

Sun May21 09:47:01 2017 - [warning] HealthCheck: SSH to 192.168.244.10is NOT reachable.

Monitoring server192.168.244.30 is reachable, Master is not reachable from 192.168.244.30. OK.

Sun May21 09:47:07 2017 - [info] Master is not reachable from all other monitoring servers. Failover should start.

Sun May21 09:47:07 2017 - [warning] Master is not reachable from health checker!Sun May21 09:47:07 2017 - [warning] Master 192.168.244.10(192.168.244.10:3306) is not reachable!Sun May21 09:47:07 2017 -[warning] SSH is NOT reachable.

Sun May21 09:47:07 2017 - [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..

Sun May21 09:47:07 2017 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.

Sun May21 09:47:07 2017 - [info] Reading application default configuration from /etc/masterha/app1.cnf..

Sun May21 09:47:07 2017 - [info] Reading server configuration from /etc/masterha/app1.cnf..

Sun May21 09:47:08 2017 - [info] GTID failover mode = 0Sun May21 09:47:08 2017 - [info] Dead Servers:

Sun May21 09:47:08 2017 - [info] 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:08 2017 - [info] Alive Servers:

Sun May21 09:47:08 2017 - [info] 192.168.244.20(192.168.244.20:3306)

Sun May21 09:47:08 2017 - [info] 192.168.244.30(192.168.244.30:3306)

Sun May21 09:47:08 2017 - [info] Alive Slaves:

Sun May21 09:47:08 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled

Sun May21 09:47:08 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:08 2017 - [info] Primary candidate forthe new Master (candidate_master is set)

Sun May21 09:47:08 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled

Sun May21 09:47:08 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:08 2017 - [info] Checking slave configurations..

Sun May21 09:47:08 2017 - [info] Checking replication filtering settings..

Sun May21 09:47:08 2017 - [info] Replication filtering check ok.

Sun May21 09:47:08 2017 - [info] Master is down!Sun May21 09:47:08 2017 - [info] Terminating monitoring script.

Sun May21 09:47:08 2017 - [info] Got exit code 20(Master dead).

Sun May21 09:47:08 2017 - [info] MHA::MasterFailover version 0.56.

Sun May21 09:47:08 2017 - [info] Starting master failover.

Sun May21 09:47:08 2017 - [info]

Sun May21 09:47:08 2017 - [info] * Phase 1: Configuration Check Phase..

Sun May21 09:47:08 2017 - [info]

Sun May21 09:47:09 2017 - [info] GTID failover mode = 0Sun May21 09:47:09 2017 - [info] Dead Servers:

Sun May21 09:47:09 2017 - [info] 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:09 2017 - [info] Checking master reachability via MySQL(doublecheck)...

Sun May21 09:47:09 2017 - [info] ok.

Sun May21 09:47:09 2017 - [info] Alive Servers:

Sun May21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306)

Sun May21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306)

Sun May21 09:47:09 2017 - [info] Alive Slaves:

Sun May21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled

Sun May21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:09 2017 - [info] Primary candidate forthe new Master (candidate_master is set)

Sun May21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled

Sun May21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:09 2017 - [info] Starting Non-GTID based failover.

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] ** Phase 1: Configuration Check Phase completed.

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] * Phase 2: Dead Master Shutdown Phase..

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] Forcing shutdown so that applications never connect to the current master..

Sun May21 09:47:09 2017 - [info] Executing master IP deactivation script:

Sun May21 09:47:09 2017 - [info] /usr/local/bin/master_ip_failover --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --command=stop

Disabling the VIP an old master:192.168.244.10Sun May21 09:47:09 2017 - [info] done.

Sun May21 09:47:09 2017 -[warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.

Sun May21 09:47:09 2017 - [info] * Phase 2: Dead Master Shutdown Phase completed.

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] * Phase 3: Master Recovery Phase..

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] * Phase 3.1: Getting Latest Slaves Phase..

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] The latest binary log file/position on all slaves is mysql-bin.000001:37651149Sun May21 09:47:09 2017 - [info] Latest slaves (Slaves that received relay log files to the latest):

Sun May21 09:47:09 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled

Sun May21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:09 2017 - [info] Primary candidate forthe new Master (candidate_master is set)

Sun May21 09:47:09 2017 - [info] The oldest binary log file/position on all slaves is mysql-bin.000001:35083093Sun May21 09:47:09 2017 - [info] Oldest slaves:

Sun May21 09:47:09 2017 - [info] 192.168.244.30(192.168.244.30:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled

Sun May21 09:47:09 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..

Sun May 21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [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.

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] * Phase 3.3: Determining New Master Phase..

Sun May21 09:47:09 2017 - [info]

Sun May21 09:47:09 2017 - [info] Finding the latest slave that has all relay logs forrecovering other slaves..

Sun May21 09:47:10 2017 - [info] HealthCheck: SSH to 192.168.244.20is reachable.

Sun May21 09:47:10 2017 - [info] Checking whether 192.168.244.20has relay logs from the oldest position..

Sun May21 09:47:10 2017 - [info] Executing command: apply_diff_relay_logs --command=find --latest_mlf=mysql-bin.000001 --latest_rmlp=37651149 --target_mlf=mysql-bin.000001 --target_rmlp=35083093 --server_id=2 --workdir=/tmp --timestamp=20170521094708 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/:

Opening/var/lib/mysql/relay-log.info... ok.

Relay log found at/var/lib/mysql, up to mysqld-relay-bin.000004Fast relay log position search succeeded.

Target relay logfile/position found. start_file:mysqld-relay-bin.000004, start_pos:35083256.

Target relay log FOUND!Sun May21 09:47:11 2017 - [info] OK. 192.168.244.20has all relay logs.

Sun May21 09:47:11 2017 - [info] HealthCheck: SSH to 192.168.244.30is reachable.

Sun May21 09:47:13 2017 - [info] Searching new master from slaves..

Sun May21 09:47:13 2017 - [info] Candidate masters from the configuration file:

Sun May21 09:47:13 2017 - [info] 192.168.244.20(192.168.244.20:3306) Version=5.6.31-log (oldest major version between slaves) log-bin:enabled

Sun May21 09:47:13 2017 - [info] Replicating from 192.168.244.10(192.168.244.10:3306)

Sun May21 09:47:13 2017 - [info] Primary candidate forthe new Master (candidate_master is set)

Sun May21 09:47:13 2017 - [info] Non-candidate masters:

Sun May21 09:47:13 2017 - [info] Searching from candidate_master slaves whichhave received the latest relay log events..

Sun May21 09:47:13 2017 - [info] New master is 192.168.244.20(192.168.244.20:3306)

Sun May21 09:47:13 2017 - [info] Starting master failover..

Sun May21 09:47:13 2017 - [info]

From:192.168.244.10(192.168.244.10:3306) (current master)+--192.168.244.20(192.168.244.20:3306)+--192.168.244.30(192.168.244.30:3306)

To:192.168.244.20(192.168.244.20:3306) (new master)+--192.168.244.30(192.168.244.30:3306)

Sun May21 09:47:13 2017 - [info]

Sun May21 09:47:13 2017 - [info] * Phase 3.3: New Master Diff Log Generation Phase..

Sun May21 09:47:13 2017 - [info]

Sun May21 09:47:13 2017 - [info] This server has all relay logs. No need to generate difffiles from the latest slave.

Sun May21 09:47:13 2017 - [info]

Sun May21 09:47:13 2017 - [info] * Phase 3.4: Master Log Apply Phase..

Sun May21 09:47:13 2017 - [info]

Sun May21 09:47:13 2017 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.

Sun May21 09:47:13 2017 - [info] Starting recovery on 192.168.244.20(192.168.244.20:3306)..

Sun May21 09:47:13 2017 - [info] This server has all relay logs. Waiting all logs to be applied..

Sun May21 09:47:56 2017 - [info] done.

Sun May21 09:47:56 2017 - [info] All relay logs were successfully applied.

Sun May21 09:47:56 2017 - [info] Getting new master's binlog name and position..

Sun May 21 09:47:56 2017 - [info] mysql-bin.000010:166054508Sun May21 09:47:56 2017 - [info] All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.244.20', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000010', MASTER_LOG_POS=166054508, MASTER_USER='repl', MASTER_PASSWORD='xxx';

Sun May21 09:47:56 2017 - [info] Executing master IP activate script:

Sun May21 09:47:56 2017 - [info] /usr/local/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.244.10 --orig_master_ip=192.168.244.10 --orig_master_port=3306 --new_master_host=192.168.244.20 --new_master_ip=192.168.244.20 --new_master_port=3306 --new_master_user='monitor' --new_master_password='monitor123'Set read_only=0on the new master.

Enabling the VIP192.168.244.188 on the new master: 192.168.244.20Sun May21 09:47:59 2017 - [info] OK.

Sun May21 09:47:59 2017 - [info] **Finished master recovery successfully.

Sun May21 09:47:59 2017 - [info] * Phase 3: Master Recovery Phase completed.

Sun May21 09:47:59 2017 - [info]

Sun May21 09:47:59 2017 - [info] * Phase 4: Slaves Recovery Phase..

Sun May21 09:47:59 2017 - [info]

Sun May21 09:47:59 2017 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..

Sun May21 09:47:59 2017 - [info]

Sun May21 09:47:59 2017 - [info] -- Slave diff file generation on host 192.168.244.30(192.168.244.30:3306) started, pid: 3606. Check tmp log /masterha/app1/192.168.244.30_3306_20170521094708.log if it takes time..

Sun May21 09:48:04 2017 - [info]

Sun May21 09:48:04 2017 - [info] Log messages from 192.168.244.30...

Sun May21 09:48:04 2017 - [info]

Sun May21 09:47:59 2017 - [info] Server 192.168.244.30 received relay logs up to: mysql-bin.000001:35083093Sun May21 09:47:59 2017 - [info] Need to get diffs from the latest slave(192.168.244.20) up to: mysql-bin.000001:37651149 (using the latest slave's relay logs)

Sun May 21 09:47:59 2017 - [info] Connecting to the latest slave host 192.168.244.20, generating diffrelay log files..

Sun May21 09:47:59 2017 - [info] Executing command: apply_diff_relay_logs --command=generate_and_send --scp_user=root --scp_host=192.168.244.30 --latest_mlf=mysql-bin.000001 --latest_rmlp=37651149 --target_mlf=mysql-bin.000001 --target_rmlp=35083093 --server_id=2 --diff_file_readtolatest=/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog --workdir=/tmp --timestamp=20170521094708 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --relay_dir=/var/lib/mysql/Sun May21 09:48:04 2017 - [info]

Opening/var/lib/mysql/relay-log.info... ok.

Relay log found at/var/lib/mysql, up to mysqld-relay-bin.000004Fast relay log position search succeeded.

Target relay logfile/position found. start_file:mysqld-relay-bin.000004, start_pos:35083256.

Concat binary/relay logs from mysqld-relay-bin.000004 pos 35083256 to mysqld-relay-bin.000004 EOF into /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog ..

Binlog Checksum enabled

Binlog Checksum enabled

Dumping binlog format description event, from position0 to 283.. ok.

Dumping effective binlog data from/var/lib/mysql/mysqld-relay-bin.000004 position 35083256 to tail(37651312).. ok.

Binlog Checksum enabled

Binlog Checksum enabled

Concat succeeded.

Generatingdiff relay log succeeded. Saved at /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog .scp node2:/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog to root@192.168.244.30(22) succeeded.

Sun May21 09:48:04 2017 - [info] Generating difffiles succeeded.

Sun May21 09:48:04 2017 - [info] End of log messages from 192.168.244.30.

Sun May21 09:48:04 2017 - [info] -- Slave diff log generation on host 192.168.244.30(192.168.244.30:3306) succeeded.

Sun May21 09:48:04 2017 - [info] Generating relay difffiles from the latest slave succeeded.

Sun May21 09:48:04 2017 - [info]

Sun May21 09:48:04 2017 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..

Sun May21 09:48:04 2017 - [info]

Sun May21 09:48:04 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) started, pid: 3613. Check tmp log /masterha/app1/192.168.244.30_3306_20170521094708.log if it takes time..

Sun May21 09:48:12 2017 - [info]

Sun May21 09:48:12 2017 - [info] Log messages from 192.168.244.30...

Sun May21 09:48:12 2017 - [info]

Sun May21 09:48:04 2017 - [info] Starting recovery on 192.168.244.30(192.168.244.30:3306)..

Sun May21 09:48:04 2017 - [info] Generating diffs succeeded.

Sun May21 09:48:04 2017 - [info] Waiting untilall relay logs are applied.

Sun May21 09:48:04 2017 - [info] done.

Sun May21 09:48:04 2017 - [info] Getting slave status..

Sun May21 09:48:04 2017 - [info] This slave(192.168.244.30)'s Exec_Master_Log_Pos(mysql-bin.000001:35083010) does not equal to Read_Master_Log_Pos(mysql-bin.000001:35083093). It is likely that relay log was cut during transaction. Need to recover from Exec_Master_Log_Pos.

Sun May 21 09:48:04 2017 - [info] Saving local relay logs from exec pos to read pos on 192.168.244.30: from mysqld-relay-bin.000004:35083173to the end of the relay log..

Sun May21 09:48:04 2017 - [info] Executing command : save_binary_logs --command=save --start_file=mysqld-relay-bin.000004 --start_pos=35083173 --output_file=/tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --relay_log_info=/var/lib/mysql/relay-log.info --binlog_dir=/var/lib/mysql/Sun May21 09:48:05 2017 - [info]

Creating/tmp ifnot exists.. ok.

Concat binary/relay logs from mysqld-relay-bin.000004 pos 35083173 to mysqld-relay-bin.000004 EOF into /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog ..

Binlog Checksum enabled

Binlog Checksum enabled

Dumping binlog format description event, from position0 to 283.. ok.

Dumping effective binlog data from/var/lib/mysql/mysqld-relay-bin.000004 position 35083173 to tail(35083256).. ok.

Binlog Checksum enabled

Binlog Checksum enabled

Concat succeeded.

Sun May21 09:48:05 2017 - [info] Connecting to the target slave host 192.168.244.30, running recover script..

Sun May21 09:48:05 2017 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='monitor' --slave_host=192.168.244.30 --slave_ip=192.168.244.30 --slave_port=3306 --apply_files=/tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog,/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog --workdir=/tmp --target_version=5.6.31-log --timestamp=20170521094708 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --slave_pass=xxx

Sun May21 09:48:12 2017 - [info]

Concat all apply files to/tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog ..

Copying the first binlogfile /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog to /tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog.. ok.

Dumping binloghead events (rotate events), skipping format description events from /tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog.. Binlog Checksum enabled

Binlog Checksum enabled

dumped up to pos283. ok./tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog has effective binlog events from pos 283.

Dumping effective binlog data from/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog position 283 to tail(2568339).. ok.

Concat succeeded.

All apply target binary logs are concatinated at/tmp/total_binlog_for_192.168.244.30_3306.20170521094708.binlog .

MySQL client version is5.6.31. Using --binary-mode.

Applying differential binary/relay log files /tmp/relay_from_exec_to_read_192.168.244.30_3306_20170521094708.binlog,/tmp/relay_from_read_to_latest_192.168.244.30_3306_20170521094708.binlog on 192.168.244.30:3306. This may take long time...

Applying log files succeeded.

Sun May21 09:48:12 2017 - [info] All relay logs were successfully applied.

Sun May21 09:48:12 2017 - [info] Resetting slave 192.168.244.30(192.168.244.30:3306) and starting replication from the new master 192.168.244.20(192.168.244.20:3306)..

Sun May21 09:48:12 2017 - [info] Executed CHANGE MASTER.

Sun May21 09:48:12 2017 - [info] Slave started.

Sun May21 09:48:12 2017 - [info] End of log messages from 192.168.244.30.

Sun May21 09:48:12 2017 - [info] -- Slave recovery on host 192.168.244.30(192.168.244.30:3306) succeeded.

Sun May21 09:48:12 2017 - [info] All new slave servers recovered successfully.

Sun May21 09:48:12 2017 - [info]

Sun May21 09:48:12 2017 - [info] * Phase 5: New master cleanup phase..

Sun May21 09:48:12 2017 - [info]

Sun May21 09:48:12 2017 - [info] Resetting slave infoon the new master..

Sun May21 09:48:12 2017 - [info] 192.168.244.20: Resetting slave infosucceeded.

Sun May21 09:48:12 2017 - [info] Master failover to 192.168.244.20(192.168.244.20:3306) completed successfully.

Sun May21 09:48:12 2017 - [info] Deleted server1 entry from /etc/masterha/app1.cnf .

Sun May21 09:48:12 2017 - [info]----- Failover Report -----app1: MySQL Master failover192.168.244.10(192.168.244.10:3306) to 192.168.244.20(192.168.244.20:3306) succeeded

Master192.168.244.10(192.168.244.10:3306) is down!Check MHA Manager logs at node4:/masterha/app1/manager.log fordetails.

Started automated(non-interactive) failover.

Invalidated master IP address on192.168.244.10(192.168.244.10:3306)

The latest slave192.168.244.20(192.168.244.20:3306) has all relay logs forrecovery.

Selected192.168.244.20(192.168.244.20:3306) as a new master.192.168.244.20(192.168.244.20:3306): OK: Applying all logs succeeded.192.168.244.20(192.168.244.20:3306): OK: Activated master IP address.192.168.244.30(192.168.244.30:3306): Generating differential relay logs up to 192.168.244.20(192.168.244.20:3306)succeeded.

Generating relaydifffiles from the latest slave succeeded.192.168.244.30(192.168.244.30:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.244.20(192.168.244.20:3306)192.168.244.20(192.168.244.20:3306): Resetting slave infosucceeded.

Master failover to192.168.244.20(192.168.244.20:3306) completed successfully.

Sun May21 09:48:12 2017 - [info] Sending mail..

Unknown option: conf