“复制”作为MySQL原生的数据同步功能，在MySQL高可用架构中起着至关重要的作用。本文梳理了UCloud在运维本公司MySQL高可用产品UDB过程中遇到的复制问题，并总结了当复制发生异常时，排查复制异常的方法。
本文承接上一篇文章，通过收集到的相关复制信息和错误信息，针对几种常见的复制错误进行分析。
一、常见复制错误原因及分析过程
在收集到上述复制相关信息和错误信息后，需要根据实际的误信息进行分析，这里罗列了几种常见的复制错误，可以通过部分或者全部在前述章节收集的相关信息，分析出复制错误发生原因。
1. 从库执行语句与主库冲突
1.1 错误原因
从库执行DML语句或者DDL语句后，主库和从库会出现数据不一致的情况，从而导致主库执行的语句在从库没有办法正常执行。
1.2 错误信息
由于从库执行与主库冲突的语句而导致复制错误，常见错误信息如下：
- 创建库或者表失败
- 017-04-18T07:52:40.440723Z 6 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:2' at master log binlog001.000001, end_log_pos 493; Error 'Can't create database 'mydb4'; database exists' on query. Default database: 'mydb4'. Query: 'create database mydb4', Error_code: 1007
- 2017-04-18T07:57:35.975310Z 10 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 378; Could not execute Write_rows event on table mydb.test; Duplicate entry '10' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 378, Error_code: 1062
- [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 506; Could not execute Delete_rows event on table mydb.I1; Can't find record in 'I1', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 506, Error_code: 1032
由于这是比较常见的原因，所有导致主从冲突的操作均会导致复制出错，这里不再一一列举。
1.3 原因分析过程
这里以“由于数据库存在而导致创建数据库出错”为例来分析原因。
(1) 查看 error log
Error log中显示的详细错误信息如下：
- 2017-04-18T08:22:26.885713Z 16 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6' at master log binlog001.000001, end_log_pos 1710; Error 'Can't create database 'mydb10'; database exists' on query. Default database: 'mydb10'. Query: 'create database mydb10', Error_code: 1007
显示在执行GTID 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6时失败。错误原因在于数据库已经存在，无法创建。
(2) 查看 show slave status
当错误发生后，查看show slave status显示的信息时，会发现如下信息：
- Master_UUID: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783
- Retrieved_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5
- Executed_Gtid_Set: 0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1-5,
- 3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1
在Executed_Gtid_Set显示的信息中，除了Master的UUID对应GTID外，还存在另外一个GTID，我们可以查看从库的GTID，执行如下语句：
发现另外的GTID是由从库执行而产生。
(3) 查看从库binlog日志
从库binlog日志记录的是SQL线程复现的主机binlog信息或者是从库本身执行事务的binlog日志。这些事务可以通过server_id或者GTID来区分。
这里以创建数据库失败为例，在从库binlog中，查找3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1对应的事务，发现如下信息：
- #170418 16:22:15 server id 30002 end_log_pos 1791 CRC32 0xfa89e69a GTID last_committed=6 sequence_number=7
- SET @@SESSION.GTID_NEXT= '3a169e6c-f1d0-11e6-bb30-d4ae52a34783:1'/*!*/;
- # at 1791
- ……
- create database mydb10
(4) 查看从库relay log日志
从库relay log日志记录的是IO线程从主库接收到的binlog日志信息，我们查看执行失败的GTID对应的事务信息：
- #170418 16:22:26 server id 30001 end_log_pos 1610 CRC32 0x27c8228f GTID last_committed=5 sequence_number=6
- SET @@SESSION.GTID_NEXT= '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:6'/*!*/;
- # at 519
- ……
- create database mydb10
- /*!*/;
(5) 总结
最终可以确认是由于从库执行了创建数据库语句后，SQL线程再次执行创建数据库语句时发生复制失败的情况。
2. 主库的binlog丢失
2.1 错误原因
复制过程中，由于从库需要读取的主库binlog丢失，从而导致复制发生异常。导致主库binlog丢失的主要原因如下：
- 主库执行reset master命令
- 主库执行purge binary/master logs命令
- 主库设置了expire_logs_days，自动删除了binlog
- 主库的binlog被误删除
2.2 错误信息
如果发生找不到主机binlog的情况，从库error log会报出如下错误：
- 2017-04-18T09:01:42.894612Z 17 [ERROR] Slave I/O for channel '': Got fatal error 1236 from master when reading data from binary log: 'could not find ne
2.3 原因分析过程
(1) 查看 error log
Error log中显示的详细错误信息如下：
- 2017-04-18T09:01:42.894612Z 17 [ERROR] Slave I/O for channel '': Got fatal error 1236 from master when reading data from binary log: 'could not find next log; the first event '' at 4, the last event read from './binlog001.000002' at 154, the last byte read from './binlog001.000002' at 154.', Error_code: 1236
错误信息显示无法找到对应的binlog文件。
(2) 查看 binlog 日志
查看主库的binlog日志文件列表，可能会发现主库的binlog变成重新开始记录：
- -rw-r----- 1 songlei.wang songlei.wang 449 Apr 18 17:01 binlog001.000001
- -rw-r----- 1 songlei.wang songlei.wang 19 Apr 18 17:01 binlog_index001.index
或者需要复制的binlog已经被删除：
- -rw-r----- 1 songlei.wang songlei.wang 241 Apr 18 17:12 binlog001.000006
- -rw-r----- 1 songlei.wang songlei.wang 1716 Apr 18 17:12 binlog001.000007
- -rw-r----- 1 songlei.wang songlei.wang 194 Apr 18 17:12 binlog001.000008
- -rw-r----- 1 songlei.wang songlei.wang 57 Apr 18 17:12 binlog_index001.index
(3) 总结
如果binlog重新开始记录，通常是由于主库执行了reset master命令，导致所有的binlog被删除。
如果binlog仍然在继续记录，只是从库需要的binlog被删除，通常是由于主库手动执行了purge binary logs命令，或者日志的保留时间超过了expire_logs_days设置的时间。
3. 从库没有执行主库复制的语句
3.1 错误原因
复制过程中，用于主库执行事务对应的GTID已经存在于从库GTID_EXECUTED中，那么从库便不会执行这些事务，从而导致主库和从库的数据不一致。通常有如下情况：
主机执行了reset master(从库当前读取主机的第一个binlog，并不会因为reset master而导致找不到文件)重做主从，从库没有清除从库的binlog。
3.2 错误信息
在从库忽略主机执行事务的过程中，从库复制不会报出任何错误，所以这种复制的异常容易被忽略，没有办法及时发现。
由于主库和从库的数据库不一致，后续的DML和DDL操作可能会发生执行失败的错误。
3.3 原因分析过程
这里我们以插入语句找不到对应的表为例。
(1) 查看 error log
Error log中记录错误信息：
- 2017-04-18 20:39:01 682 [ERROR] Slave SQL: Error 'Table 'mydb.mytbl2' doesn't exist' on query. Default database: 'mydb'. Query: 'insert into mydb.mytbl4 values (1)', Error_code: 1146
(2) 查看show slave status
show slave status显示的信息全部正常，无从库执行事务的binlog产生。这里不排除从库关闭binlog执行drop table操作的可能。
(3) 查看表
分别在主机和从库执行命令show create table mydb.mytbl4，发现从库上并不存在mydb.mytbl4。
(4) 解析 binlog 日志
解析主机binlog日志，查看建表的事务日志：
- #170418 20:50:47 server id 30061 end_log_pos 199 CRC32 0xaaa00818 GTID [commit=yes]
- SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;
- # at 199
- #170418 20:50:47 server id 30061 end_log_pos 319 CRC32 0x06f5789f Query thread_id=3 exec_time=0 error_code=0
- ……
- create table if not exists mydb.mytbl4 (A int)
解析从库的binlog日志，查找是否存在建表的事务日志:
- #170418 20:49:49 server id 30061 end_log_pos 199 CRC32 0x3051fade GTID [commit=yes]
- SET @@SESSION.GTID_NEXT= '1ac5f388-0dea-11e7-b2ec-d4ae52a34783:1'/*!*/;
- # at 199
- #170418 20:49:49 server id 30061 end_log_pos 278 CRC32 0x7156a1c9 Query thread_id=3 exec_time=40 error_code=0
- ……
- BEGIN
- /*!*/;
- # at 278
- #170418 20:49:49 server id 30061 end_log_pos 385 CRC32 0x25560e04 Query thread_id=3 exec_time=40 error_code=0
- use `mydb`/*!*/;
- SET TIMESTAMP=1492519789/*!*/;
- insert into mydb.mytbl values (1)
- /*!*/;
- ……
这时我们发现对于相同的GTID，从库和主机执行的语句不相同。
(5) 总结
通过上述分析，我们推断是从库并没有执行建表语句，进而导致主库数据不一致。
(6) 说明
这种情况MySQL-5.7版本会在复制时有更严格校验，如果主机发送GTID要少于从库的GTID，那么会报告出如下的错误：
- Got fatal error 1236 from master when reading data from binary log: 'Slave has more GTIDs than the master has, using the master's SERVER_UUID. This may indicate that the end of the binary log was truncated or that the last binary log file was lost, e.g., after a power or disk failure when sync_binlog != 1. The master may or may not have rolled back transactions that were already replica', Error_code: 1236
但是，即使在5.7版本，如果启动复制时(错误后重新启动)，主库执行的GTID超过了从库，仍然会报出同样的错误。
4. 主库执行了不进行复制的语句
4.1 错误原因
主库上执行的操作并不会写入binlog，因此这里不考虑主库主动关闭binlog的情况。
4.2 错误信息
由于主库和从库的数据不一致，导致主库执行的操作复制到从库后，发生从库执行失败的情况。如：
创建FEDERATED引擎的表失败：
- 2017-01-24T08:04:31.682038Z 3 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '887ca716-e202-11e6-8a82-52540086ae59:7' at master log mysql-bin.000004, end_log_pos 906; Error 'server name: 's' doesn't exist!' on query. Default database: 'mydb'. Query: 'CREATE TABLE `mytbl` (
- `idaction` int(10) unsigned NOT NULL AUTO_INCREMENT,
4.3 原因分析过程
这里以使用CONNECTION创建FEDERATED引擎的表为例。
(1) 查看error log
Error log中记录错误信息：
- 2017-01-24T08:04:31.682038Z 3 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '887ca716-e202-11e6-8a82-52540086ae59:7' at master log mysql-bin.000004, end_log_pos 906; Error 'server name: 's' doesn't exist!' on query.
(2) 查看主库和从库的server表
- 主库中server表中存在名字为s的记录。
- 从库中不存在名字为s的记录。
(3) 查看CREATE SERVER文档说明
文档中记录的create server语句并不会记录到binlog中，所以导致主库和从库的数据不一致，复制无法正常进行。
(4) 总结
对于不记入binlog的操作，需要主库和从库同时执行，以防发生主库和从库不一致的情况。
5. 从库重复执行relay log的语句(非GTID，非多线程复制)
5.1 错误原因
如果物理机发生宕机或者从库发生意外中断，那么可能发生SQL线程已经执行过了某一个relay log中的事务，但是这个事务对应文件和位置信息并没有及时更新到relay_log.info中的情况。在从库发生重启之后，会将执行过的事务再次重新执行。
5.2 错误信息
重复执行的事务包括任何记录到relay log中的事务，可能出现的错误信息包括：
- 创建库或者表失败
- 2017-04-18T07:52:40.440723Z 6 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:2' at master log binlog001.000001, end_log_pos 493; Error 'Can't create database 'mydb4'; database exists' on query. Default database: 'mydb4'. Query: 'create database mydb4', Error_code: 1007
- 2017-04-18T07:57:35.975310Z 10 [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 378; Could not execute Write_rows event on table mydb.test; Duplicate entry '10' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log FIRST, end_log_pos 378, Error_code: 1062
- [ERROR] Slave SQL for channel '': Worker 0 failed executing transaction '0c1b77a7-c113-11e6-9bd6-d4ae52a34783:1' at master log binlog001.000001, end_log_pos 506; Could not execute Delete_rows event on table mydb.I1; Can't find record in 'I1', Error_code: 1032; handler error HA_ERR_END_OF_FILE; the event's master log FIRST, end_log_pos 506, Error_code: 1032
由于各种类型的事务均可能执行，这里不再一一列举。
5.3 原因分析过程
这里以插入语句主键冲突为例
(1) 查看error log
Error log中记录以下报错信息：
- 2017-04-19T03:02:15.448429Z 4 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'binlog001.000001' at position 403, relay log './relaylog002.000002' position: 616
- 2017-04-19T03:02:15.459468Z 4 [ERROR] Slave SQL for channel '': Could not execute Write_rows event on table mydb.k2; Duplicate entry '101' for key 'PRIMARY', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log binlog001.000001, end_log_pos 621, Error_code: 1062
- 2017-04-19T03:02:15.459526Z 4 [Warning] Slave: Duplicate entry '101' for key 'PRIMARY' Error_code: 1062
可以看到是SQL线程在启动后执行第一个事务就发生主键冲突的错误。
(2) 查看show slave status
show slave status显示的信息全部正常，无从库执行事务的binlog产生。
(3) mydb.k2
表中已经存在了这条记录。
(4) mydb.k2
查看从库的relay log，从复制的起始位置./relaylog002.000002：616查看：
- #170419 11:00:22 server id 30001 end_log_pos 403 CRC32 0x0ef99927 Xid = 7395
- COMMIT/*!*/;
- # at 616 relay log的文件位置
- #170419 11:00:59 server id 30001 end_log_pos 468 CRC32 0xbd3fd6d7 Anonymous_GTID last_committed=1 sequence_number=2 对应主机的事务执行的时间
- SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
- # at 681
- #170419 11:00:59 server id 30001 end_log_pos 536 CRC32 0x484841bd Query thread_id=553 exec_time=0 error_code=0
- SET TIMESTAMP=1492570859/*!*/;
- BEGIN
- /*!*/;
- # at 749
- #170419 11:00:59 server id 30001 end_log_pos 581 CRC32 0x9fd66b9e Table_map: `mydb`.`k2` mapped to number 114
- # at 794
- #170419 11:00:59 server id 30001 end_log_pos 621 CRC32 0x4151da88 Write_rows: table id 114 flags: STMT_END_F
- BINLOG '
- 69L2WBMxdQAALQAAAEUCAAAAAHIAAAAAAAEABG15ZGIAAmsyAAEDAACea9af
- 69L2WB4xdQAAKAAAAG0CAAAAAHIAAAAAAAEAAgAB//5lAAAAiNpRQQ==
- '/*!*/;
- ### INSERT INTO `mydb`.`k2`
- ### SET
- ### @1=101
- # at 834
- #170419 11:00:59 server id 30001 end_log_pos 652 CRC32 0xf876844e Xid = 7396
- COMMIT/*!*/;
查看从库的binlog：
- #170419 11:00:59 server id 30001 end_log_pos 463 CRC32 0x6ede3a0d Anonymous_GTID last_committed=1 sequence_number=2
- SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
- # at 463
- #170419 11:00:59 server id 30001 end_log_pos 526 CRC32 0x5fac2d32 Query thread_id=553 exec_time=0 error_code=0
- SET TIMESTAMP=1492570859/*!*/;
- BEGIN
- /*!*/;
- # at 526
- #170419 11:00:59 server id 30001 end_log_pos 571 CRC32 0xb51f8ec9 Table_map: `mydb`.`k2` mapped to number 108
- # at 571
- #170419 11:00:59 server id 30001 end_log_pos 611 CRC32 0xfa578a3f Write_rows: table id 108 flags: STMT_END_F
- BINLOG '
- 69L2WBMxdQAALQAAADsCAAAAAGwAAAAAAAEABG15ZGIAAmsyAAEDAADJjh+1
- 69L2WB4xdQAAKAAAAGMCAAAAAGwAAAAAAAEAAgAB//5lAAAAP4pX+g==
- '/*!*/;
- ### INSERT INTO `mydb`.`k2`
- ### SET
- ### @1=101
- # at 611
- #170419 11:00:59 server id 30001 end_log_pos 642 CRC32 0xc3a619a0 Xid = 12
- COMMIT/*!*/;
(5) 总结
通过分析上述binlog内容，relay log中并没有记录相同的insert语句，但从库的binlog显示已经执行过该语句，当从库重启后，试图再次执行相同的insert语句，从而导致插入语句的主键冲突。
(6) 说明
如果复制使用GTID，那么GTID的特性会使从库不执行相同的语句。
如果在5.7版本使用多线程复制，那么mts_recovery会修复这个问题。
只有在非多线程复制、非GTID复制的情况下才可能出现这个错误。
二、总结
如果复制发生了错误，通过收集上述复制相关信息和错误相关信息，分析这些信息中与正常复制异常的地方，便可为排查复制错误提供更多的信息。
当然，复制的错误是多种多样的，并不是所有的错误都可以排查到具体原因。很多复制错误是较难或者无法进行排查的，比如主库或者从库的binlog日志文件已经丢失、关闭binlog后执行某些操作导致复制不一致，又或者某些内核BUG导致MySQL的复制逻辑本身发生了异常等。
【本文是51CTO专栏机构作者“大U的技术课堂”的原创文章，转载请通过微信公众号(ucloud2012)联系作者】
