MySQL之MHA+keepalived方案演示(四)

sm702

[root@server02 ~]# pkill mysqld　　[root@server03 masterha]# tailf /var/log/masterha/app1/manager.log
　　Sun Jul  1 17:04:27 2018 - [warning] Got error on MySQL select ping: 2006 (MySQL server has gone away)
　　Sun Jul  1 17:04:27 2018 - [info] Executing SSH check script: save_binary_logs --command=test --start_pos=4 --binlog_dir=/data/mysql/logs/bin-log --output_file=/tmp/save_binary_logs_test --manager_version=0.56 --binlog_prefix=mysql-bin
　　Sun Jul  1 17:04:27 2018 - [info] Executing secondary network check script: /usr/local/bin/masterha_secondary_check -s server03 -s server02 --user=root --master_host=server02 --master_ip=192.168.2.128 --master_port=3306  --user=root  --master_host=192.168.2.128  --master_ip=192.168.2.128  --master_port=3306 --master_user=monitor --master_password=123456 --ping_type=SELECT
　　Monitoring server server03 is reachable, Master is not reachable from server03. OK.
　　Sun Jul  1 17:04:28 2018 - [info] HealthCheck: SSH to 192.168.2.128 is reachable.
　　Monitoring server server02 is reachable, Master is not reachable from server02. OK.
　　Sun Jul  1 17:04:28 2018 - [info] Master is not reachable from all other monitoring servers. Failover should start.
　　Sun Jul  1 17:04:28 2018 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
　　Sun Jul  1 17:04:28 2018 - [warning] Connection failed 2 time(s)..
　　Sun Jul  1 17:04:29 2018 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
　　Sun Jul  1 17:04:29 2018 - [warning] Connection failed 3 time(s)..
　　Sun Jul  1 17:04:30 2018 - [warning] Got error on MySQL connect: 2013 (Lost connection to MySQL server at 'reading initial communication packet', system error: 111)
　　Sun Jul  1 17:04:30 2018 - [warning] Connection failed 4 time(s)..
　　Sun Jul  1 17:04:30 2018 - [warning] Master is not reachable from health checker!
　　Sun Jul  1 17:04:30 2018 - [warning] Master 192.168.2.128(192.168.2.128:3306) is not reachable!
　　Sun Jul  1 17:04:30 2018 - [warning] SSH is reachable.
　　Sun Jul  1 17:04:30 2018 - [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 Jul  1 17:04:30 2018 - [warning] Global configuration file /etc/masterha_default.cnf not found. Skipping.
　　Sun Jul  1 17:04:30 2018 - [info] Reading application default configuration from /etc/masterha/app1.cnf..
　　Sun Jul  1 17:04:30 2018 - [info] Reading server configuration from /etc/masterha/app1.cnf..
　　Sun Jul  1 17:04:31 2018 - [info] GTID failover mode = 0
　　Sun Jul  1 17:04:31 2018 - [info] Dead Servers:
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info] Alive Servers:
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.129(192.168.2.129:3306)
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.130(192.168.2.130:3306)
　　Sun Jul  1 17:04:31 2018 - [info] Alive Slaves:
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.129(192.168.2.129:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info]     Primary candidate for the new Master (candidate_master is set)
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.130(192.168.2.130:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info] Checking slave configurations..
　　Sun Jul  1 17:04:31 2018 - [info]  read_only=1 is not set on slave 192.168.2.129(192.168.2.129:3306).
　　Sun Jul  1 17:04:31 2018 - [info] Checking replication filtering settings..
　　Sun Jul  1 17:04:31 2018 - [info]  Replication filtering check ok.
　　Sun Jul  1 17:04:31 2018 - [info] Master is down!
　　Sun Jul  1 17:04:31 2018 - [info] Terminating monitoring script.
　　Sun Jul  1 17:04:31 2018 - [info] Got exit code 20 (Master dead).
　　Sun Jul  1 17:04:31 2018 - [info] MHA::MasterFailover version 0.56.
　　Sun Jul  1 17:04:31 2018 - [info] Starting master failover.
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] * Phase 1: Configuration Check Phase..
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] GTID failover mode = 0
　　Sun Jul  1 17:04:31 2018 - [info] Dead Servers:
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info] Checking master reachability via MySQL(double check)...
　　Sun Jul  1 17:04:31 2018 - [info]  ok.
　　Sun Jul  1 17:04:31 2018 - [info] Alive Servers:
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.129(192.168.2.129:3306)
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.130(192.168.2.130:3306)
　　Sun Jul  1 17:04:31 2018 - [info] Alive Slaves:
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.129(192.168.2.129:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info]     Primary candidate for the new Master (candidate_master is set)
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.130(192.168.2.130:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info] Starting Non-GTID based failover.
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] ** Phase 1: Configuration Check Phase completed.
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] * Phase 2: Dead Master Shutdown Phase..
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] Forcing shutdown so that applications never connect to the current master..
　　Sun Jul  1 17:04:31 2018 - [info] Executing master IP deactivation script:
　　Sun Jul  1 17:04:31 2018 - [info]   /usr/local/bin/master_ip_failover --orig_master_host=192.168.2.128 --orig_master_ip=192.168.2.128 --orig_master_port=3306 --command=stopssh --ssh_user=root
　　Sun Jul  1 17:04:31 2018 - [info]  done.
　　Sun Jul  1 17:04:31 2018 - [warning] shutdown_script is not set. Skipping explicit shutting down of the dead master.
　　Sun Jul  1 17:04:31 2018 - [info] * Phase 2: Dead Master Shutdown Phase completed.
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] * Phase 3: Master Recovery Phase..
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] * Phase 3.1: Getting Latest Slaves Phase..
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] The latest binary log file/position on all slaves is mysql-bin.000006:154

　　Sun Jul  1 17:04:31 2018 - [info] Latest slaves (Slaves that received>　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.129(192.168.2.129:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info]     Primary candidate for the new Master (candidate_master is set)
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.130(192.168.2.130:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info] The oldest binary log file/position on all slaves is mysql-bin.000006:154
　　Sun Jul  1 17:04:31 2018 - [info] Oldest slaves:
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.129(192.168.2.129:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info]     Primary candidate for the new Master (candidate_master is set)
　　Sun Jul  1 17:04:31 2018 - [info]   192.168.2.130(192.168.2.130:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:31 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] * Phase 3.2: Saving Dead Master's Binlog Phase..
　　Sun Jul  1 17:04:31 2018 - [info]
　　Sun Jul  1 17:04:31 2018 - [info] Fetching dead master's binary logs..
　　Sun Jul  1 17:04:31 2018 - [info] Executing command on the dead master 192.168.2.128(192.168.2.128:3306): save_binary_logs --command=save --start_file=mysql-bin.000006  --start_pos=154 --binlog_dir=/data/mysql/logs/bin-log --output_file=/tmp/saved_master_binlog_from_192.168.2.128_3306_20180701170431.binlog --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56
　　Creating /tmp if not exists..    ok.
　　Concat binary/relay logs from mysql-bin.000006 pos 154 to mysql-bin.000006 EOF into /tmp/saved_master_binlog_from_192.168.2.128_3306_20180701170431.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/logs/bin-log/mysql-bin.000006 (pos starts 154, filesize 154). Skipping.
　　Binlog Checksum enabled
　　/tmp/saved_master_binlog_from_192.168.2.128_3306_20180701170431.binlog has no effective data events.
　　Event not exists.
　　Sun Jul  1 17:04:32 2018 - [info] Additional events were not found from the orig master. No need to save.
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 3.3: Determining New Master Phase..
　　Sun Jul  1 17:04:32 2018 - [info]

　　Sun Jul  1 17:04:32 2018 - [info] Finding the latest slave that has all>
　　Sun Jul  1 17:04:32 2018 - [info] All slaves received>　　Sun Jul  1 17:04:32 2018 - [info] Searching new master from slaves..
　　Sun Jul  1 17:04:32 2018 - [info]  Candidate masters from the configuration file:
　　Sun Jul  1 17:04:32 2018 - [info]   192.168.2.129(192.168.2.129:3306)  Version=5.7.21-log (oldest major version between slaves) log-bin:enabled
　　Sun Jul  1 17:04:32 2018 - [info]     Replicating from 192.168.2.128(192.168.2.128:3306)
　　Sun Jul  1 17:04:32 2018 - [info]     Primary candidate for the new Master (candidate_master is set)
　　Sun Jul  1 17:04:32 2018 - [info]  Non-candidate masters:

　　Sun Jul  1 17:04:32 2018 - [info]  Searching from candidate_master slaves which have received the latest>　　Sun Jul  1 17:04:32 2018 - [info] New master is 192.168.2.129(192.168.2.129:3306)
　　Sun Jul  1 17:04:32 2018 - [info] Starting master failover..
　　Sun Jul  1 17:04:32 2018 - [info]
　　From:
　　192.168.2.128(192.168.2.128:3306) (current master)
　　+--192.168.2.129(192.168.2.129:3306)
　　+--192.168.2.130(192.168.2.130:3306)
　　To:
　　192.168.2.129(192.168.2.129:3306) (new master)
　　+--192.168.2.130(192.168.2.130:3306)
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 3.3: New Master Diff Log Generation Phase..
　　Sun Jul  1 17:04:32 2018 - [info]

　　Sun Jul  1 17:04:32 2018 - [info]  This server has all>　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 3.4: Master Log Apply Phase..
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
　　Sun Jul  1 17:04:32 2018 - [info] Starting recovery on 192.168.2.129(192.168.2.129:3306)..

　　Sun Jul  1 17:04:32 2018 - [info]  This server has all>　　Sun Jul  1 17:04:32 2018 - [info]   done.

　　Sun Jul  1 17:04:32 2018 - [info]  All>　　Sun Jul  1 17:04:32 2018 - [info] Getting new master's binlog name and position..
　　Sun Jul  1 17:04:32 2018 - [info]  mysql-bin.000003:154
　　Sun Jul  1 17:04:32 2018 - [info]  All other slaves should start replication from here. Statement should be: CHANGE MASTER TO MASTER_HOST='192.168.2.129', MASTER_PORT=3306, MASTER_LOG_FILE='mysql-bin.000003', MASTER_LOG_POS=154, MASTER_USER='repmha', MASTER_PASSWORD='xxx';
　　Sun Jul  1 17:04:32 2018 - [info] Executing master IP activate script:
　　Sun Jul  1 17:04:32 2018 - [info]   /usr/local/bin/master_ip_failover --command=start --ssh_user=root --orig_master_host=192.168.2.128 --orig_master_ip=192.168.2.128 --orig_master_port=3306 --new_master_host=192.168.2.129 --new_master_ip=192.168.2.129 --new_master_port=3306 --new_master_user='monitor' --new_master_password='123456'
　　Undefined subroutine &main::FIXME_xxx_create_user called at /usr/local/bin/master_ip_failover line 88.
　　Set read_only=0 on the new master.
　　Creating app user on the new master..
　　Sun Jul  1 17:04:32 2018 - [error][/usr/share/perl5/vendor_perl/MHA/MasterFailover.pm, ln1588]  Failed to activate master IP address for 192.168.2.129(192.168.2.129:3306) with return code 10:0
　　Sun Jul  1 17:04:32 2018 - [warning] Proceeding.
　　Sun Jul  1 17:04:32 2018 - [info] ** Finished master recovery successfully.
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 3: Master Recovery Phase completed.
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 4: Slaves Recovery Phase..
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 4.1: Starting Parallel Slave Diff Log Generation Phase..
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] -- Slave diff file generation on host 192.168.2.130(192.168.2.130:3306) started, pid: 49563. Check tmp log /var/log/masterha/app1.log/192.168.2.130_3306_20180701170431.log if it takes time..
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] Log messages from 192.168.2.130 ...
　　Sun Jul  1 17:04:32 2018 - [info]

　　Sun Jul  1 17:04:32 2018 - [info]  This server has all>　　Sun Jul  1 17:04:32 2018 - [info] End of log messages from 192.168.2.130.

　　Sun Jul  1 17:04:32 2018 - [info] -- 192.168.2.130(192.168.2.130:3306) has the latest>
　　Sun Jul  1 17:04:32 2018 - [info] Generating>　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 4.2: Starting Parallel Slave Log Apply Phase..
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] -- Slave recovery on host 192.168.2.130(192.168.2.130:3306) started, pid: 49565. Check tmp log /var/log/masterha/app1.log/192.168.2.130_3306_20180701170431.log if it takes time..
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] Log messages from 192.168.2.130 ...
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] Starting recovery on 192.168.2.130(192.168.2.130:3306)..

　　Sun Jul  1 17:04:32 2018 - [info]  This server has all>　　Sun Jul  1 17:04:32 2018 - [info]   done.

　　Sun Jul  1 17:04:32 2018 - [info]  All>　　Sun Jul  1 17:04:32 2018 - [info]  Resetting slave 192.168.2.130(192.168.2.130:3306) and starting replication from the new master 192.168.2.129(192.168.2.129:3306)..
　　Sun Jul  1 17:04:32 2018 - [info]  Executed CHANGE MASTER.
　　Sun Jul  1 17:04:32 2018 - [info]  Slave started.
　　Sun Jul  1 17:04:32 2018 - [info] End of log messages from 192.168.2.130.
　　Sun Jul  1 17:04:32 2018 - [info] -- Slave recovery on host 192.168.2.130(192.168.2.130:3306) succeeded.
　　Sun Jul  1 17:04:32 2018 - [info] All new slave servers recovered successfully.
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] * Phase 5: New master cleanup phase..
　　Sun Jul  1 17:04:32 2018 - [info]
　　Sun Jul  1 17:04:32 2018 - [info] Resetting slave info on the new master..
　　Sun Jul  1 17:04:32 2018 - [info]  192.168.2.129: Resetting slave info succeeded.
　　Sun Jul  1 17:04:32 2018 - [info] Master failover to 192.168.2.129(192.168.2.129:3306) completed successfully.
　　Sun Jul  1 17:04:32 2018 - [info] Deleted server1 entry from /etc/masterha/app1.cnf .
　　Sun Jul  1 17:04:32 2018 - [info]
　　----- Failover Report -----
　　app1: MySQL Master failover 192.168.2.128(192.168.2.128:3306) to 192.168.2.129(192.168.2.129:3306) succeeded
　　Master 192.168.2.128(192.168.2.128:3306) is down!
　　Check MHA Manager logs at server04:/var/log/masterha/app1/manager.log for details.
　　Started automated(non-interactive) failover.
　　Invalidated master IP address on 192.168.2.128(192.168.2.128:3306)

　　The latest slave 192.168.2.129(192.168.2.129:3306) has all>　　Selected 192.168.2.129(192.168.2.129:3306) as a new master.
　　192.168.2.129(192.168.2.129:3306): OK: Applying all logs succeeded.
　　Failed to activate master IP address for 192.168.2.129(192.168.2.129:3306) with return code 10:0

　　192.168.2.130(192.168.2.130:3306): This host has the latest>
　　Generating>　　192.168.2.130(192.168.2.130:3306): OK: Applying all logs succeeded. Slave started, replicating from 192.168.2.129(192.168.2.129:3306)
　　192.168.2.129(192.168.2.129:3306): Resetting slave info succeeded.
　　Master failover to 192.168.2.129(192.168.2.129:3306) completed successfully.
　　Sun Jul  1 17:04:32 2018 - [info] Sending mail..
　　Unknown option: conf