MySQL主从同步异常操作处理

============主从复制涉及的日志
****Master_Log_File，Read_MAster_Log_Pos
Master_Log_File，Read_MAster_Log_Pos记录了IO线程读到的当前master binlog文件和位置，对应master的binlog文件和位置

****Realy_Log_File，Realy_Log_Pos
Realy_Log_File，Realy_Log_Pos记录了sql线程执行到realy log的哪个文件和位置，对应的是slave上的realy log文件和位置

****Realy_Master_Log_File，Exec_Matser_Log_Pos
Realy_Master_Log_File，Exec_Matser_Log_Pos记录的是sql线程执行到matser binlog的文件和位置，对应的master上的binlog的文件和位置

select * from mysql.slave_relay_log_info \G
select * from mysql.slave_master_info\G
mysql -uroot -h 10.3.5.22 -P3306 -p'rootmysql' -e "SHOW SLAVE STATUS \G"|egrep -i 'Slave_IO_Running|Slave_SQL_Running|Replicate_Wild_Do_Table|Replicate_Wild_Ignore_Table|Seconds_Behind_Master|Channel_Name|Last_IO_Errno|Last_IO_Error|Last_SQL_Errno|Last_SQL_Error|Exec_Master_Log_Pos'

1、传统基于二进制坐标的复制中，从库由于某些错误导致复制中断时，一个可能的解决方案是设置sql_slave_skip_counter全局系统变量，跳过导致错误的事件，然后重启复制。

2、但启用GTID后，执行的单位由事件变为事务，因此该方法不再有效。
mysql> set global sql_slave_skip_counter=1;
ERROR 1858 (HY000): sql_slave_skip_counter can not be set when the server is running with @@GLOBAL.GTID_MODE = ON. Instead, for each transaction that you want to skip, generate an empty transaction with the same GTID as the transaction
mysql>
从错误消息可以看到，GTID跳过事务的方法是注入一个空事务，具体步骤为：
（1）定位出错事务的GTID，从库报错我们需要获得从库执行的最后一个事务，方法有：
show slave status \G                 # 中的Executed_Gtid_Set
show global variables like '%gtid%'; # gtid_executed
show master status;                  # 中的Executed_Gtid_Set

（2）将会话级系统变量gtid_next设置为上一步的GTID，如。
stop slave;
set gtid_next='46760eb0-bcb3-11e9-a352-24a9c4e7e87e:73'; # Retrieved_Gtid_Set: 46760eb0-bcb3-11e9-a352-24a9c4e7e87e:66-73
begin;
commit;
set GTID_NEXT='AUTOMATIC';
start slave;

3、跳过具体报错号
如跳过1062报错，设置参数 slave_skip_errors=1062 ，重启 MySQL
待主从同步正常后，再取消参数 slave_skip_errors 设置，重启 MySQL 

gtid方式  
mysql> stop slave;
mysql> set GTID_NEXT='46760eb0-bcb3-11e9-a352-24a9c4e7e87e:79';  # Retrieved_Gtid_Set: 46760eb0-bcb3-11e9-a352-24a9c4e7e87e:66-79
mysql> begin;
mysql> commit;
mysql> set GTID_NEXT='AUTOMATIC';
mysql> start slave;
mysql> show slave status\G;

注：传统方式
mysql> stop slave;
mysql> SET GLOBAL SQL_SLAVE_SKIP_COUNTER = n;  
mysql> start slave;
mysql> show slave status\G;


-- 在从库上执行
mysql> show slave status\G;
                   Last_Error: Coordinator stopped because there were error(s) in the worker(s). The most recent failure being: Worker 1 failed executing transaction '46760eb0-bcb3-11e9-a352-24a9c4e7e87e:73' at master log mysql-bin.000002, end_log_pos 703142. See error log and/or performance_schema.replication_applier_status_by_worker table for more details about this failure or others, if any.
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 702860
          Relay_Master_Log_File: mysql-bin.000002
--主库上解析binlog
mysqlbinlog -v --base64-output=decode mysql-bin.000002 --start-position=702860 >2.log
# at 702860
#190813 11:22:24 server id 3306  end_log_pos 702939 CRC32 0x4ffade6b     GTID    last_committed=72    sequence_number=73    rbr_only=yes    original_committed_timestamp=1565666544911622    immediate_commit_timestamp=1565666544911622    transaction_length=313
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
# original_commit_timestamp=1565666544911622 (2019-08-13 11:22:24.911622 CST)
# immediate_commit_timestamp=1565666544911622 (2019-08-13 11:22:24.911622 CST)
/*!80001 SET @@session.original_commit_timestamp=1565666544911622*//*!*/;
/*!80014 SET @@session.original_server_version=80017*//*!*/;
/*!80014 SET @@session.immediate_server_version=80017*//*!*/;
SET @@SESSION.GTID_NEXT= '46760eb0-bcb3-11e9-a352-24a9c4e7e87e:73'/*!*/;


====================================================================2、常见问题汇总及解决
2.1、主、从库数据表字符集不一致
2.1.1、报错信息
Last_SQL_Errno: 1677
Last_SQL_Error: Column 1 of table 'XXX' cannot be converted from type 'varchar(150(bytes))' to type 'varchar(110(bytes))'
2.1.2、解决方案
1> 主、从库查看数据表的字符集信息
mysql> show create table 表名;

2> 从库执行如下命令
mysql> stop slave;
mysql> alter table table_name convert to character set 主库数据表字符集;
mysql> start slave;
mysql> show slave status;

2.2、主库删除从库不存在数据
2.2.1、报错信息
Last_Errno: 1032
Last_SQL_Error: Could not execute Delete_rows event on table XXX; Can't find record in 'XXX', 
Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND;
2.2.2、解决方案
2.2.2.1、方案1--从库插入不存在数据，然后开启数据同步
1> 在从库执行如下命令：
mysql> show slave status; 
找到Exec_Master_Log_Pos的值，例如：XXXX；Last_Error信息中的end_log_pos的值，例如：YYYYYY

2> 在主库使用自带的mysqlbinlog查看删除信息：
cd /usr/bin
mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS --start-position=XXXX --stop-position=YYYYYY /var/lib/mysql/binlog.000001
说明：

主库mysqlbinlog所在文件夹位置，可以使用如下命令查找：
whereis mysqlbinlog

3> 找到删除语句之后，在从库插入删除数据，例如：
insert into test values(1, 'jack');

4> 在从库执行如下命令
mysql> start slave;
mysql> show slave status;
插入数据时，如果遇到索引冲突的问题，可参考如下操作：
mysql插入数据时，出现Duplicate entry 'XXX' for key 'XXX'的问题：
可以使用replace into,
replace into是insert into的增强版：
(1) 如果插入的数据不重复，执行的是insert into操作，影响1条记录
(2) 如果插入的数据重复，执行的是update操作，影响2条记录：先删除旧的数据，再插入新的数据。
示例：
replace into test values(1,'jack'）

2.2.2.2、方案2--从库直接跳过GTID
1> 在从库中执行如下命令
mysql> show slave status\G;
找到同步失败时主库log位置，即Exec_Master_Log_Pos的值，例如：XXXX；同时从Last_Error信息中找到同步失败的binlog文件名，例如：binlog.000021

2> 在主库中查询执行如下语句
mysql> show binlog events IN 'binlog.000021' FROM XXXX limit 10;
找到XXXX对应的SESSION.GTID_NEXT值，例如：ZZZZZ

3> 在从库中执行如下语句
mysql> stop slave;
mysql> set GTID_NEXT='ZZZZZ';
mysql> begin;commit;
mysql> set GTID_NEXT='AUTOMATIC';
mysql> start slave;
mysql> show slave status;

上面方法只能跳过一个事务，那么对于一批事务跳过，参考如下指令：

（1）主库执行如下语句
mysql> show master status;
根据查询结果，找到 Executed_Gtid_Set 字段对应的值，例如：2a09ee6e-645d-11e7-a96c-000c2953a1cb:1-19345623

（2）在从库中执行如下语句
mysql> stop slave;
mysql> reset master;
mysql> set global gtid_purged='2a09ee6e-645d-11e7-a96c-000c2953a1cb:1-19345623';
mysql> start slave;
mysql> show slave status;

2.3、主库更新从库不存在数据
2.3.1、报错信息
Last_Errno: 1032
Last_Error: Could not execute Update_rows event on table XXX; Can't find record in 'XXXX', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log binlog.0000XX, end_log_pos XXXXX
2.3.2、解决方案
1> 在从库执行如下命令：
mysql> show slave status; 
# 也可使用：
mysql> show slave status\G; 
找到Exec_Master_Log_Pos的值，例如：XXXX；Last_Error信息中的end_log_pos的值，例如：YYYYYY

2> 在主库使用mysqlbinlog查看更新操作的数据：
mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS --start-position=XXXX --stop-position=YYYYYY /var/lib/mysql/binlog.000001
3> 在主库中查看更新之后的数据，然后将这些数据导出；并在从库执行插入语句插入数据。

4> 在主库中查询执行事件：
mysql> show binlog events IN 'binlog.000001' FROM XXXX limit 50;
找到XXXX对应的SESSION.GTID_NEXT值 ZZZZZ

5> 在从库中执行如下语句
mysql> stop slave;
mysql> set GTID_NEXT='ZZZZZ';
mysql> begin;commit;
mysql> set GTID_NEXT='AUTOMATIC';
mysql> start slave;
mysql> show slave status;

2.4、从库连接数不足导致同步失败
2.4.1、报错信息
Slave_IO_State: connecting to master
Last_IO_Error: MySql Host is blocked because of many connection errors; unblock with 'mysqladmin flush-hosts'
2.4.2、解决方案
1> 主、从数据库都要查看max_connection_errors

(1) 进入主、从库Mysql数据库查看max_connection_errors
mysql> show variables like '%max_connect_errors%';
(2) 修改max_connection_errors的数量为1000
mysql> set global max_connect_errors = 1000;
(3) 查看是否修改成功
mysql> show variables like '%max_connect_errors%'; 
2> 在主、从库下清理一下hosts文件
mysql> flush hosts;

2.5、主库下caching_sha2_password插件导致连接异常
2.5.1、报错信息
Last_IO_Error: error connecting to master 'repl@192.168.91.131:3306' - retry-time: 60 retries: 7 message: Authentication plugin 'caching_sha2_password' reported error: Authentication requires secure connection.
2.5.2、解决方案
1> 在主库下数据库名为 mysql下的 user表，查看 user为repl 信息
mysql> SELECT plugin FROM `mysql`.`user` where user = 'repl';

2> 修改主库mysql下的 user表中repl对应的mysql_native_password (新旧密码可以保持一致)
mysql> ALTER USER 'repl'@'%' IDENTIFIED WITH mysql_native_password BY '123456';

2.6、主从数据同步报错1782
2.6.1、报错信息
Last_Errno: 1782
Last_Error: Error executing row event: '@@SESSION.GTID_NEXT cannot be set to ANONYMOUS when @@GLOBAL.GTID_MODE = ON.'
2.6.2、解决方案
在从库中执行如下命令：
mysql> stop slave sql_thread;
mysql> set GLOBAL GTID_MODE = ON_PERMISSIVE;
mysql> set GLOBAL GTID_MODE = OFF_PERMISSIVE;
mysql> set GLOBAL GTID_MODE = OFF;
mysql> start slave sql_thread;
mysql> start slave;
mysql> show slave status;

2.7、主从数据同步报错1781
2.7.1、报错信息
Last_Errno: 1781
Last_Error: @@SESSION.GTID_NEXT cannot be set to UUID:NUMBER when @@GLOBAL.GTID_MODE = OFF.
2.7.2、解决方案
在从库中执行如下命令：
mysql> set GLOBAL GTID_MODE = OFF_PERMISSIVE;
mysql> set GLOBAL GTID_MODE = ON_PERMISSIVE;
mysql> set GLOBAL GTID_MODE = ON;
mysql> start slave;
mysql> show slave status;

2.8、从库存在数据，主库插入相同数据同步失败
说明：此种情况是从库存在数据，导致主库在插入相同数据时，从库数据同步报错。

2.8.1、报错信息
Last_Errno: 1062
Last_Error: Could not execute Write_rows event on table XXXX.xxx; Duplicate entry 'XXX' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log binlog.XXXXXXX, end_log_pos XXXXXXX
2.8.2、解决方案
针对此种情况，保证以主库数据为主，同时删除从库数据时需要考虑从库表数据主键是否为自增。
mysql> stop slave;
mysql> delete from XXXX.xxx where 主键字段='XXX';
mysql> start slave;
mysql> show slave status;

2.9、中继日志损坏
2.9.1、报错信息
Last_SQL_Error: Error initializing relay log position: I/O error reading the header from the binary log
Last_SQL_Error: Error initializing relay log position: Binlog has bad magic number;  
It's not a binary log file that can be used by this version of MySQL
2.9.2、解决方案
说明：找到同步的binlog和POS点，然后重新做同步，这样就可以有新的中继日志
1> 在从库查找执行的中继日志Relay_Master_Log_File和Exec_Master_Log_Pos节点
mysql> show slave status\G;
获取 Relay_Master_Log_File 值(例如：binlog.xxxxx) 和 Exec_Master_Log_Pos 值(例如：YYYYYY)

2> 在从库执行如下命令
mysql> stop slave;
mysql> CHANGE MASTER TO MASTER_LOG_FILE='binlog.xxxxx', MASTER_LOG_POS=YYYYYY;
mysql> start slave;
mysql> show slave status\G;
====================================================================未完待续~~~~~~~~~~~~~~~~~~~



1.1. MySQL版本
SELECT @@VERSION;

1.2. binlog 相关参数
select @@log_bin,@@log_slave_updates;

+-----------+---------------------+
| @@log_bin | @@log_slave_updates |
+-----------+---------------------+
| 1 | 1 |
+-----------+---------------------+

1.3. GTID 相关参数
select  @@binlog_gtid_simple_recovery,@@enforce_gtid_consistency,@@gtid_mode;

+-------------------------------+----------------------------+-------------+
| @@binlog_gtid_simple_recovery | @@enforce_gtid_consistency | @@gtid_mode |
+-------------------------------+----------------------------+-------------+
| 1 | ON | ON |
+-------------------------------+----------------------------+-------------+

1.4. 半同步相关参数
show global variables like '%semi%';

+-------------------------------------------+------------+
| Variable_name | Value |
+-------------------------------------------+------------+
| rpl_semi_sync_master_enabled | ON |
| rpl_semi_sync_master_timeout | 1000 |
| rpl_semi_sync_master_trace_level | 32 |
| rpl_semi_sync_master_wait_for_slave_count | 1 |
| rpl_semi_sync_master_wait_no_slave | ON |
| rpl_semi_sync_master_wait_point | AFTER_SYNC |
| rpl_semi_sync_slave_enabled | ON |
| rpl_semi_sync_slave_trace_level | 32 |
+-------------------------------------------+------------+

1.5. 多线程同步相关参数
select @@binlog_transaction_dependency_tracking,@@slave_parallel_type,@@slave_parallel_workers;

+------------------------------------------+-----------------------+---------
-----------------+
| @@binlog_transaction_dependency_tracking | @@slave_parallel_type |
@@slave_parallel_workers |
+------------------------------------------+-----------------------+---------
-----------------+
| COMMIT_ORDER | LOGICAL_CLOCK |
2 |
+------------------------------------------+-----------------------+---------
-----------------+
1 row in set (0.00 sec)

2.故障现象
MySQL 从库所在主机故障重启后，sql_thread 线程报错：
 show slave status\G
-- 摘取有用信息如下：
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1062
Last_Error: Coordinator stopped because there were
error(s) in the worker(s). The most recent failure being: Worker 1 failed
executing transaction '471c2974-f9bb-11eb-afb1-52540010fb89:88313207' at master
log MySql-bin.000685, end_log_pos 1004756557. See error log and/or
performance_schema.replication_applier_status_by_worker table for more details
about this failure or others, if any.
......省略..................
Retrieved_Gtid_Set: 471c2974-f9bb-11eb-afb1-
52540010fb89:88313207-88341912
Executed_Gtid_Set: 471c2974-f9bb-11eb-afb1-52540010fb89:1-
88313206,
d4c228df-f9c6-11eb-a2d8-5254006f63b6:1-5
Auto_Position: 1
root@3306 (none)> select * from
performance_schema.replication_applier_status_by_worker\G
*************************** 1. row ***************************
CHANNEL_NAME:
WORKER_ID: 1
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 471c2974-f9bb-11eb-afb1-52540010fb89:88313207
LAST_ERROR_NUMBER: 1062
LAST_ERROR_MESSAGE: Worker 1 failed executing transaction '471c2974-f9bb-
11eb-afb1-52540010fb89:88313207' at master log MySql-bin.000685, end_log_pos
1004756557; Could not execute Write_rows event on table kefumobile.i_sms_proxy;
Duplicate entry '14765130' for key 'PRIMARY', Error_code: 1062; handler error
HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 1004756557
LAST_ERROR_TIMESTAMP: 2022-01-24 23:05:02
*************************** 2. row ***************************
CHANNEL_NAME:
WORKER_ID: 2
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION:
LAST_ERROR_NUMBER: 0
LAST_ERROR_MESSAGE:
LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
2 rows in set (0.00 sec)

通过报错信息可知，worker 线程在回放事务'471c2974-f9bb-11eb-afb1-52540010fb89:88313207'时，由于要插入的记录主键冲突报错。

3.故障分析
主机重启前，主从同步正常，主机重启后，主从同步由于主键冲突报错，对比了冲突主键所在行记 录在主从库是一致的，初步分析事务'471c2974-f9bb-11eb-afb1-52540010fb89:88313207'

在主机故 障前已经在从库进行了回放，那为何事务会重复回放呢？
在开启gtid模式下，如果指定 master_auto_position=1，start slave 时，从库会把 Retrieved_Gtid_Set 和 Executed_Gtid_Set 的并集发送给主库，
主库将收到的并集和自己的 gtid_executed 比较，把从库 gtid 集合里缺失的事务全都发送给从库。
主机重启后，事务重复回放，表明 Retrieved_Gtid_Set 和 Executed_Gtid_Set 的并集中有 GTID 事务 丢失，导致重复获取事务执行引发主键冲突错误。

Retrieved_Gtid_Set 和 Executed_Gtid_Set 均为内存变 量，MySQL 重启后，Retrieved_Gtid_Set 初始化为空值，从而推断出 Executed_Gtid_Set 有 GTID 事务丢 失。
Executed_Gtid_Set 来源于 gtid_executed 变量，gtid_executed 变量持久化介质有 mysql.gtid_executed 表和 binlog ，
其中 mysql.gtid_executed 表是 MySQL 5.7 后引入的，在 MySQL 5.6 中，从库要使用 GTID ，必须要先设置 log_bin=on,log_slave_updates=on ，因为从库执行过的 GTID 只保留在 binlog 中。
当 log_bin=on ，log_slave_updates=off 时，gtid_executed 变量的更新实时持久化到 mysql.gtid_executed 表中，MySQL 重启后 gtid_executed 变量值从 mysql.gtid_executed 表读取。
当 log_bin=on ，log_slave_updates=on 时，只有在 binlog 切换时侯才会更新 mysql.gtid_executed 表，保存直到上一个 binlog 执行过的 GTID 集合。
mysql 重启后，在默认参数 binlog_gtid_simple_recovery=1 时，gtid_executed 变量值从最后一个 binlog 文件计算获得。

gtid_executed 变量值陈旧，推断出 binlog 未实时持久化，我们看一下参数 sync_binlog :
show variables like 'sync_binlog';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| sync_binlog | 600 |
+---------------+-------+
1 row in set (0.00 sec)
通过以上分析，此次故障来龙去脉就清楚了：

Worker 线程报 1062 主键冲突错误 --> gtid_executed 信息陈旧 --> binlog 未实时持久化

4.测试验证
搭建一主一从测试环境，通过 sysbench 模拟主库并发插入，从库主机暴力关机后，故障复现：

root@mysql.sock][(none)]> select * from performance_schema.replication_applier_status_by_worker \G
*************************** 1. row ***************************
CHANNEL_NAME:
WORKER_ID: 1
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION: 4a0ad3da-b89e-11eb-9d0b-000c299b4d6c:452362
LAST_ERROR_NUMBER: 1062
LAST_ERROR_MESSAGE: Worker 1 failed executing transaction '4a0ad3da-b89e-
11eb-9d0b-000c299b4d6c:452362' at master log MySql-bin.000012, end_log_pos
1011339749; Could not execute Write_rows event on table sbtest.sbtest5;
Duplicate entry '111305' for key 'PRIMARY', Error_code: 1062; handler error
HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 1011339749
LAST_ERROR_TIMESTAMP: 2022-01-26 09:56:38
*************************** 2. row ***************************
CHANNEL_NAME:
WORKER_ID: 2
THREAD_ID: NULL
SERVICE_STATE: OFF
LAST_SEEN_TRANSACTION:
LAST_ERROR_NUMBER: 0
LAST_ERROR_MESSAGE:
LAST_ERROR_TIMESTAMP: 0000-00-00 00:00:00
2 rows in set (0.00 sec)
[root@mysql.sock][(none)]>

5.故障处理
既然错误原因是事务重复执行，那跳过错误就好了，有如下两种方式，根据需要选取其中一种方式执行：

5.1.通过空事务替代报错事务执行
set gtid_next='xxxxxx';
begin;
commit;
set gtid_next=AUTOMATIC;
start slave sql_thread

如果最新 binglog 丢失的 GTID 较多，手工执行比较繁琐，需要不断试错。可写一个存储过程批量执行：

set sql_log_bin=0;
DELIMITER $$
create procedure p_fx_gtid_next(i_master_Executed_Gtid_max varchar(100))
begin
declare v_gtid_next varchar(100);
declare master_Executed_Gtid_max varchar(100);
declare slave_Executed_Gtid_max varchar(100);
-- 主库当前执行了的gtid最大值，做为退出循环条件 show master status
set master_Executed_Gtid_max=i_master_Executed_Gtid_max;
loop_name:loop
SELECT ifnull(min(LAST_SEEN_TRANSACTION),'empty') FROM
performance_schema.replication_applier_status_by_worker WHERE
LAST_ERROR_NUMBER=1062
into v_gtid_next;
if v_gtid_next <> 'empty' then
set gtid_next = v_gtid_next;
start transaction;
commit;
set gtid_next =AUTOMATIC;
start slave sql_thread;
end if;
select max(LAST_SEEN_TRANSACTION) from
performance_schema.replication_applier_status_by_worker into
slave_Executed_Gtid_max;
if slave_Executed_Gtid_max = master_Executed_Gtid_max then
leave loop_name;
end if;
select SLEEP(1);
end loop;
end $$
DELIMITER ;
set sql_log_bin=1;
call p_fx_gtid_next('XXXXX:XXX');

5.2.带参数 slave_skip_errors=1062 重启 MySQL
待主从同步正常后，再取消参数 slave_skip_errors 设置重启 MySQL 。