MHA-Failover可能遇到的坑

一、主从数据一致性

1.1、如何保证主从数据一致性

在MySQL中，一次事务提交后，需要写undo、写redo、写binlog，写数据文件等等。在这个过程中，可能在某个步骤发生crash，就有可能导致主从数据的不一致。为了避免这种情况，我们需要调整主从上面相关选项配置，确保即便发生crash了，也不能发生主从复制的数据丢失。
MASTER上修改配置
innodb_flush_log_at_trx_commit = 1 --> redo log 1写磁盘、2写系统缓存(操作系统挂可能丢数据)、0写redo log buffer(mysql挂可能丢数据)
sync_binlog = 1 --> binlog 1写磁盘、0写系统缓存
保证每次事务提交后，都能实时刷新到磁盘中，尤其是确保每次事务对应的binlog都能及时刷新到磁盘中
SLAVE上修改配置
master_info_repository = "TABLE"
relay_log_info_repository = "TABLE"
relay_log_recovery = 1
确保在slave上和复制相关的元数据表也采用InnoDB引擎，受到InnoDB事务安全的保护；开启relay-log自动修复机制，发生crash时根据relay_log_info中记录的已执行的binlog位置从master上重新抓取回来再次应用，以此避免部分数据丢失的可能性。

这样配置后，正常情况下主从数据应该是一致的~

1.2、主从数据不一致，复制状态正常

• binlog_format='STATEMENT'
只要复制语句对应的表结构一致，主从数据是否一致不会影响复制状态
• binlog_format='ROW'
1、有主键/唯一索引的情况下，slave应用relay-log的过程只需匹配主键/唯一索引即可，不会考虑其他列与master上的原始值是否一致
2、slave update/delete master上永远不会访问的数据
一致性的保证，需要定期使用pt工具检测并同步啦●-●

二、relay_log_recovery && relay_log_purge

参考文章：MySQL relay_log_purge=0 时的风险

有时候，我们希望将MySQL的relay-log多保留一段时间，比如用于高可用切换后的数据补齐，于是就会设置relay_log_purge=0，禁止SQL_Thread在执行完一个relay-log后自动将其删除。
relay_log_recovery=1 && relay_log_purge=0会有什么坑
• 由于崩溃或停止MySQL时，SQL_Thread可能没有执行完全部的relay-log，最后一个relay-log中的一部分数据会被重新获取到新的文件中。也就是说，这部分数据重复了两次
• 如果SQL_Thread跟得很紧，则可能在IO_Thread写入relay-log，但还没有同步到磁盘时，就已经读取执行了。这时，就会造成新的文件和旧的文件中少了一部分数据

对于复制来说这样不会有什么影响，但如果我们读取relay-log来获取数据，必须注意这一点，否则就会造成数据不一致

三、MHA-Failover可能遇到的坑

传统复制环境，MHA利用Latest Slave的relay-log去补全其他Slave的与Latest Slave之间的差异数据；GTID环境，通过change master to利用binlog补全数据，不再依赖relay-log
为了方便模拟，本文选择手动Failover来检测MHA遇到上面提到的坑会出现什么现象？本文使用MHA-手动Failover流程(传统复制&GTID复制)中的基本环境

3.1、relay-log重复

人为暂停SQL_Thread，再关闭MySQL实例，模拟SQL_Thread没有执行完全部的relay-log

relay_log_recovery=1 && relay_log_purge=0
#测试数据简写如下
Node1写入第一条记录->Node3停止io_thread
Node1写入第二条记录->
    1、Node2从库stop slave sql_thread;
    2、Node1主库写入一条新数据row_new
    3、Node2从库shutdown;
    4、Node2从库启动mysql，start slave;
Node2停止io_thread
Node1写入第三条记录

View Code

暂停从库的SQL_Thread，主库写入新数据，新数据被IO_Thread获取写入到relay-log，然后重新启动从库的mysql实例，IO_Thread根据relay_log_info中记录的已执行的binlog位置从master上重新抓取回来再次应用，因此在relay-log中可以解析到row_new获取过两次~

[root@ZST3 app1]# masterha_master_switch --global_conf=/etc/masterha/masterha_default.conf --conf=/etc/masterha/app1.conf --dead_master_host=192.168.85.132 --dead_master_port=3307 --master_state=dead --new_master_host=192.168.85.134 --new_master_port=3307 --ignore_last_failover
...
Fri Apr 13 18:09:37 2018 - [info] * Phase 3.4: Master Log Apply Phase..
Fri Apr 13 18:09:37 2018 - [info] 
Fri Apr 13 18:09:37 2018 - [info] *NOTICE: If any error happens from this phase, manual recovery is needed.
Fri Apr 13 18:09:37 2018 - [info] Starting recovery on 192.168.85.134(192.168.85.134:3307)..
Fri Apr 13 18:09:37 2018 - [info]  Generating diffs succeeded.
Fri Apr 13 18:09:37 2018 - [info] Waiting until all relay logs are applied.
Fri Apr 13 18:09:37 2018 - [info]  done.
Fri Apr 13 18:09:37 2018 - [debug]  Stopping SQL thread on 192.168.85.134(192.168.85.134:3307)..
Fri Apr 13 18:09:37 2018 - [debug]   done.
Fri Apr 13 18:09:37 2018 - [info] Getting slave status..
Fri Apr 13 18:09:37 2018 - [info] This slave(192.168.85.134)''s Exec_Master_Log_Pos equals to Read_Master_Log_Pos(mysql-bin.000005:484). No need to recover from Exec_Master_Log_Pos.
Fri Apr 13 18:09:37 2018 - [debug] Current max_allowed_packet is 4194304.
Fri Apr 13 18:09:37 2018 - [debug] Tentatively setting max_allowed_packet to 1GB succeeded.
Fri Apr 13 18:09:37 2018 - [info] Connecting to the target slave host 192.168.85.134, running recover script..
Fri Apr 13 18:09:37 2018 - [info] Executing command: apply_diff_relay_logs --command=apply --slave_user='mydba' --slave_host=192.168.85.134 --slave_ip=192.168.85.134  --slave_port=3307 --apply_files=/var/log/masterha/app1/relay_from_read_to_latest_192.168.85.134_3307_20180413180912.binlog,/var/log/masterha/app1/saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog --workdir=/var/log/masterha/app1 --target_version=5.7.21-log --timestamp=20180413180912 --handle_raw_binlog=1 --disable_log_bin=0 --manager_version=0.56 --debug  --slave_pass=xxx
Fri Apr 13 18:09:45 2018 - [info] 
 Concat all apply files to /var/log/masterha/app1/total_binlog_for_192.168.85.134_3307.20180413180912.binlog ..
 Copying the first binlog file /var/log/masterha/app1/relay_from_read_to_latest_192.168.85.134_3307_20180413180912.binlog to /var/log/masterha/app1/total_binlog_for_192.168.85.134_3307.20180413180912.binlog.. ok.
  Dumping binlog head events (rotate events), skipping format description events from /var/log/masterha/app1/saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog.. parse_init_headers: file=saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog event_type=15 server_id=1323307 length=119 nextmpos=123 prevrelay=4 cur(post)relay=123
 Binlog Checksum enabled
parse_init_headers: file=saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog event_type=35 server_id=1323307 length=31 nextmpos=154 prevrelay=123 cur(post)relay=154
 Got previous gtids log event: 154.
parse_init_headers: file=saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog event_type=34 server_id=1323307 length=65 nextmpos=1209 prevrelay=154 cur(post)relay=219
dumped up to pos 154. ok.
 /var/log/masterha/app1/saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog has effective binlog events from pos 154.
  Dumping effective binlog data from /var/log/masterha/app1/saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog position 154 to tail(507).. ok.
 Concat succeeded.
All apply target binary logs are concatinated at /var/log/masterha/app1/total_binlog_for_192.168.85.134_3307.20180413180912.binlog .
MySQL client version is 5.7.21. Using --binary-mode.
Applying differential binary/relay log files /var/log/masterha/app1/relay_from_read_to_latest_192.168.85.134_3307_20180413180912.binlog,/var/log/masterha/app1/saved_master_binlog_from_192.168.85.132_3307_20180413180912.binlog on 192.168.85.134:3307. This may take long time...
FATAL: applying log files failed with rc 1:0!
Error logs from ZST3:/var/log/masterha/app1/relay_log_apply_for_192.168.85.134_3307_20180413180912_err.log (the last 200 lines)..
mysql: [Warning] Using a password on the command line interface can be insecure.
...
ERROR 1062 (23000) at line 92: Duplicate entry '3' for key 'PRIMARY'
--------------
BINLOG '
NoDQWhMrMRQAPwAAAAMEAAAAAG4AAAAAAAEACXJlcGxjcmFzaAAHcHlfdXNlcgAEAw8SDwVgAAAe
AA7JJu9M
NoDQWh4rMRQAVgAAAFkEAAAAAG4AAAAAAAEAAgAE//ADAAAAIGM3MzExZWQ0LTNmMDEtMTFlOC05
ODg4LTAwMGMyOWMxmZ+bIJ4HMTMyMzMwN3PJaGg=
'
--------------

Bye
 at /usr/bin/apply_diff_relay_logs line 515
        eval {...} called at /usr/bin/apply_diff_relay_logs line 475
        main::main() called at /usr/bin/apply_diff_relay_logs line 120
Fri Apr 13 18:09:45 2018 - [debug] Setting max_allowed_packet back to 4194304 succeeded.
Fri Apr 13 18:09:45 2018 - [error][/usr/share/perl5/vendor_perl/MHA/MasterFailover.pm, ln1398]  Applying diffs failed with return code 22:0.
Fri Apr 13 18:09:45 2018 - [error][/usr/share/perl5/vendor_perl/MHA/MasterFailover.pm, ln1561] Recovering master server failed.
Fri Apr 13 18:09:45 2018 - [error][/usr/share/perl5/vendor_perl/MHA/ManagerUtil.pm, ln177] Got ERROR:  at /usr/bin/masterha_master_switch line 53
Fri Apr 13 18:09:45 2018 - [debug]  Disconnected from 192.168.85.133(192.168.85.133:3307)
Fri Apr 13 18:09:45 2018 - [debug]  Disconnected from 192.168.85.134(192.168.85.134:3307)
Fri Apr 13 18:09:45 2018 - [info] 

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

app1: MySQL Master failover 192.168.85.132(192.168.85.132:3307)

Master 192.168.85.132(192.168.85.132:3307) is down!

Check MHA Manager logs at ZST3 for details.

Started manual(interactive) failover.
Invalidated master IP address on 192.168.85.132(192.168.85.132:3307)
The latest slave 192.168.85.133(192.168.85.133:3307) has all relay logs for recovery.
Selected 192.168.85.134(192.168.85.134:3307) as a new master.
Recovering master server failed.
Got Error so could not continue failover from here.
[root@ZST3 app1]#

View Code

MHA切换会报错！原因就是Node3获取Latest Slave上的数据，会有重复记录，导致应用差异日志时报错。relay_from_read_to_latest_**里面也能看到有重复数据

3.2、relay-log缺失

要模拟SQL_Thread跟得比较紧不太好实现，但是可以变相模拟从库缺失relay-log的情况

relay_log_recovery=1 && relay_log_purge=1
#测试数据简写如下
Node1写入第一条记录->Node3停止io_thread
Node1写入第二条记录->Node2执行两次flush relay logs;->Node2停止io_thread
Node1写入第三条记录

View Code

目的是将第二条记录相关的relay-log给purge掉，这样Latest Slave上就没有足够的relay-log用于其他Slave的恢复

[root@ZST3 app1]# masterha_master_switch --global_conf=/etc/masterha/masterha_default.conf --conf=/etc/masterha/app1.conf --dead_master_host=192.168.85.132 --dead_master_port=3307 --master_state=dead --new_master_host=192.168.85.134 --new_master_port=3307 --ignore_last_failover
...
Fri Apr 13 15:26:39 2018 - [info] * Phase 3.3: Determining New Master Phase..
Fri Apr 13 15:26:39 2018 - [info] 
Fri Apr 13 15:26:39 2018 - [info] Finding the latest slave that has all relay logs for recovering other slaves..
Fri Apr 13 15:26:39 2018 - [info] Checking whether 192.168.85.133 has relay logs from the oldest position..
Fri Apr 13 15:26:39 2018 - [info] Executing command: apply_diff_relay_logs --command=find --latest_mlf=mysql-bin.000001 --latest_rmlp=1303 --target_mlf=mysql-bin.000001 --target_rmlp=643 --server_id=1333307 --workdir=/var/log/masterha/app1 --timestamp=20180413152622 --manager_version=0.56 --relay_log_info=/data/mysql/mysql3307/data/relay-log.info  --relay_dir=/data/mysql/mysql3307/data/  --debug  :
    Opening /data/mysql/mysql3307/data/relay-log.info ... ok.
    Relay log found at /data/mysql/mysql3307/data, up to relay-bin.000004
 Fast relay log position search failed. Reading relay logs to find..
Reading relay-bin.000004
parse_init_headers: file=relay-bin.000004 event_type=15 server_id=1333307 length=119 nextmpos=123 prevrelay=4 cur(post)relay=123
 Binlog Checksum enabled
parse_init_headers: file=relay-bin.000004 event_type=35 server_id=1333307 length=31 nextmpos=154 prevrelay=123 cur(post)relay=154
 Got previous gtids log event: 154.
parse_init_headers: file=relay-bin.000004 event_type=15 server_id=1323307 length=119 nextmpos=0 prevrelay=154 cur(post)relay=273
 Master Version is 5.7.21-log
 Binlog Checksum enabled
parse_init_headers: file=relay-bin.000004 event_type=34 server_id=1323307 length=65 nextmpos=1038 prevrelay=273 cur(post)relay=338
get_starting_mlp: file=relay-bin.000004 event_type=2 server_id=1323307 length=85 next=1123
 relay-bin.000004 contains master mysql-bin.000001 from position 1123
Reading relay-bin.000003
parse_init_headers: file=relay-bin.000003 event_type=15 server_id=1333307 length=119 nextmpos=123 prevrelay=4 cur(post)relay=123
 Binlog Checksum enabled
parse_init_headers: file=relay-bin.000003 event_type=35 server_id=1333307 length=31 nextmpos=154 prevrelay=123 cur(post)relay=154
 Got previous gtids log event: 154.
parse_init_headers: file=relay-bin.000003 event_type=15 server_id=1323307 length=119 nextmpos=0 prevrelay=154 cur(post)relay=273
parse_init_headers: file=relay-bin.000003 event_type=4 server_id=1333307 length=47 nextmpos=320 prevrelay=273 cur(post)relay=320
Reading relay-bin.000002
No such file or directory:/data/mysql/mysql3307/data/relay-bin.000002 at /usr/share/perl5/vendor_perl/MHA/BinlogPosFindManager.pm line 102
Fri Apr 13 15:26:40 2018 - [warning] 192.168.85.133 does not have all relay logs. Maybe some logs were purged.
Fri Apr 13 15:26:40 2018 - [warning] None of latest servers have enough relay logs from oldest position. We can not recover oldest slaves.
Fri Apr 13 15:26:40 2018 - [error][/usr/share/perl5/vendor_perl/MHA/MasterFailover.pm, ln947] None of the latest slaves has enough relay logs for recovery.
Fri Apr 13 15:26:40 2018 - [error][/usr/share/perl5/vendor_perl/MHA/ManagerUtil.pm, ln177] Got ERROR:  at /usr/bin/masterha_master_switch line 53
Fri Apr 13 15:26:40 2018 - [debug]  Disconnected from 192.168.85.133(192.168.85.133:3307)
Fri Apr 13 15:26:40 2018 - [debug]  Disconnected from 192.168.85.134(192.168.85.134:3307)
Fri Apr 13 15:26:40 2018 - [info] 

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

app1: MySQL Master failover 192.168.85.132(192.168.85.132:3307)

Master 192.168.85.132(192.168.85.132:3307) is down!

Check MHA Manager logs at ZST3 for details.

Started manual(interactive) failover.
Invalidated master IP address on 192.168.85.132(192.168.85.132:3307)
None of the latest slaves has enough relay logs for recovery.
Got Error so could not continue failover from here.
[root@ZST3 app1]#

View Code

MHA切换会报错！原因是Latest Slave没有包含足够的relay-log用于其他Slave的恢复操作
这样看来MHA需要relay-log恢复数据的过程，如果relay-log重复或者缺失会直接报错，切换失败！！！
自动切换先找出所有配置candidate_master=1的[server]，再从中找出日志最新的，如果有多个日志最新的，那就按[server]的先后顺序来选new master
传统复制环境，如果选择了"问题Slave"作为Latest Slave，不管手动还是自动Failover，切换都会报错。所以尽量用GTID吧~

3.3、default-character-set

15:07 2018/7/26 补充
GTID环境，执行save_binary_logs --command=save 保存Dead Master/Binlog Server和Latest Slave之间的差异数据报错
mysqlbinlog：[ERROR] unknown variable 'default-character-set=utf8'
/etc/mysql.cnf中有

[client]
default-character-set=utf8

View Code

当注释掉这行就可以正常切换(不需重启)，什么原因呢？
GTID环境save_binary_logs执行的类似这种命令

Executing command: mysqlbinlog --start-position=1013 /data/mysql/mysql3307/logs/mysql-bin.000009

mysqlbinlog类似mysqladmin会到/etc/my.cnf /etc/mysql/my.cnf /usr/local/mysql/etc/my.cnf ~/.my.cnf文件中读取[mysqladmin] [client]组
如果上述配置文件中添加前面的字符集信息，尝试打印mysqlbinlog默认参数信息

[root@ZST1 ~]# mysqlbinlog --print-defaults
mysqlbinlog would have been started with the following arguments:
--character-set-server=utf8

View Code

也就是说mysqlbinlog --start-position=1013 /data/mysql/mysql3307/logs/mysql-bin.000009，等效命令
mysqlbinlog --character-set-server=utf8 --start-position=1013 /data/mysql/mysql3307/logs/mysql-bin.000009
但是mysqlbinlog并不支持--character-set-server这样的变量所以就报错啦~
解决方法嘛，注释配置文件中的字符集信息，或者给mysqlbinlog增加一个别名：alias mysqlbinlog='mysqlbinlog --no-defaults'