复制错误案例分享（一）

作者  沈刚·沃趣科技数据库技术专家

出品  沃趣科技

MySQL Replication是MySQL非常重要的特性。用好了，可以发挥很大的作用，做负载均衡，做读写分离，做备份等等，能在关键时刻救DBA一命；用不好，那就是给DBA自己找麻烦了，处理不尽的故障。所以我这边给大家分享几个关于复制的案例。

|  案例一：binlog_format=MIXED导致的主从数据不一致

环境信息

• 操作系统 Red Hat 6.7

• 数据库版本 MySQL5.6.36

• 主从IP 

• 主库：192.168.1.36 

• 从库：192.168.1.57

• 数据库参数配置 sync_binlog=1 传统复制，即非GTID复制

故障重现

• 将两台数据库搭建成为主从架构（此处省略搭建步骤）

• 在主库（192.168.1.36）上创建测试表格，并插入测试数据

1. mysql> use test;

2. Database changed

3. mysql> create table tt(

4.    -> id int auto_increment primary key,

5.    -> int_a int,

6.    -> int_b int);

7. Query OK, 0 rows affected (0.13 sec)

8. mysql> insert into tt(`int_a`,`int_b`) values(1,1);

9. Query OK, 1 row affected (0.14 sec)

10. mysql> select * from tt;

11. +----+-------+-------+

12. | id | int_a | int_b |

13. +----+-------+-------+

14. |  1 |     1 |     1 |

15. +----+-------+-------+

16. 1 row in set (0.00 sec)

• 在从库（192.168.1.57）上检查数据以及复制状态

1. mysql> select * from tt;

2. +----+-------+-------+

3. | id | int_a | int_b |

4. +----+-------+-------+

5. |  1 |     1 |     1 |

6. +----+-------+-------+

7. 1 row in set (0.00 sec)

8. mysql> show slave status\G

9. *************************** 1. row ***************************

10.              Master_Log_File: mysql-bin.000001

11.          Read_Master_Log_Pos: 526

12.               Relay_Log_File: mysql-relay-bin.000002

13.                Relay_Log_Pos: 689

14.        Relay_Master_Log_File: mysql-bin.000001

15.             Slave_IO_Running: Yes

16.            Slave_SQL_Running: Yes

17.            .......................................部分信息省略

18.          Exec_Master_Log_Pos: 526

19.              Relay_Log_Space: 862

20.           Master_SSL_Allowed: No

21.        Seconds_Behind_Master: 0

22.                Last_IO_Errno: 0

23.                Last_IO_Error:

24.               Last_SQL_Errno: 0

25.               Last_SQL_Error:

26.  Replicate_Ignore_Server_Ids:

27.             Master_Server_Id: 3656

28.                  Master_UUID: b9e1f845-5d32-11e7-b7eb-fa163ea44438

29.             Master_Info_File: mysql.slave_master_info

30.                    SQL_Delay: 0

31.          SQL_Remaining_Delay: NULL

32.      Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it

33.           Retrieved_Gtid_Set:

34.            Executed_Gtid_Set:

35.                Auto_Position: 0

36. 1 row in set (0.00 sec)

• 接着在从库（192.168.1.57）上执行语句更新数据

1. mysql> update tt set int_b = 2 where int_a = 1;

2. Query OK, 1 row affected (0.02 sec)

3. Rows matched: 1  Changed: 1  Warnings: 0

4. mysql> select * from tt;

5. +----+-------+-------+

6. | id | int_a | int_b |

7. +----+-------+-------+

8. |  1 |     1 |     2 |

9. +----+-------+-------+

10. 1 row in set (0.00 sec)

• 在主库（192.168.1.36）上执行语句更新数据

1. mysql> update tt set int_a = 2 where int_b = 1;

2. Query OK, 1 row affected (0.02 sec)

3. Rows matched: 1  Changed: 1  Warnings: 0

4. mysql> select * from tt;

5. +----+-------+-------+

6. | id | int_a | int_b |

7. +----+-------+-------+

8. |  1 |     2 |     1 |

9. +----+-------+-------+

10. 1 row in set (0.00 sec)

• 在从库（192.168.1.57）上检查数据和复制状态，可以看到主库的操作并没有在从库上生效，并且主从的复制状态也是正常的。

1. mysql> select * from tt;

2. +----+-------+-------+

3. | id | int_a | int_b |

4. +----+-------+-------+

5. |  1 |     1 |     2 |

6. +----+-------+-------+

7. 1 row in set (0.00 sec)

8. mysql> show slave status\G

9. *************************** 1. row ***************************

10.              Master_Log_File: mysql-bin.000001

11.          Read_Master_Log_Pos: 749

12.               Relay_Log_File: mysql-relay-bin.000002

13.                Relay_Log_Pos: 912

14.        Relay_Master_Log_File: mysql-bin.000001

15.             Slave_IO_Running: Yes

16.            Slave_SQL_Running: Yes

17.            .......................................部分信息省略

18.                 Skip_Counter: 0

19.          Exec_Master_Log_Pos: 749

20.              Relay_Log_Space: 1085

21.        Seconds_Behind_Master: 0

22. Master_SSL_Verify_Server_Cert: No

23.                Last_IO_Errno: 0

24.                Last_IO_Error:

25.               Last_SQL_Errno: 0

26.               Last_SQL_Error:

27.  Replicate_Ignore_Server_Ids:

28.             Master_Server_Id: 3656

29.                  Master_UUID: b9e1f845-5d32-11e7-b7eb-fa163ea44438

30.             Master_Info_File: mysql.slave_master_info

31.                    SQL_Delay: 0

32.          SQL_Remaining_Delay: NULL

33.      Slave_SQL_Running_State: Slave has read all relay log; waiting for the slave I/O thread to update it

34.           Retrieved_Gtid_Set:

35.            Executed_Gtid_Set:

36.                Auto_Position: 0

37. 1 row in set (0.00 sec)

现象

在测试步骤中我们可以看到，在从库更新数据之后，主库上的更新操作在从库上没有生效，但是查看复制状态一切正常。仅从show slave status\G中查看到的信息，我们认为目前主从的复制是正常的，但是考虑实际的数据，主从的数据已经不一致了。

故障分析

看到主库的更新操作没有在从库上应用，首先考虑，这个事务的binlog是否真的被从库接收到。于是检查从库上的relay log，使用mysqlbinlog工具解析relay log

1. # at 689

2. #170705 13:50:49 server id 3656  end_log_pos 605 CRC32 0xe7ffbc45     Query   thread_id=9 exec_time=0 error_code=0

3. SET TIMESTAMP=1499233849/*!*/;

4. BEGIN

5. /*!*/;

6. # at 768

7. #170705 13:50:49 server id 3656  end_log_pos 718 CRC32 0xa9da82f4     Query   thread_id=9 exec_time=0 error_code=0

8. SET TIMESTAMP=1499233849/*!*/;

9. update tt set int_a = 2 where int_b = 1

10. /*!*/;

11. # at 881

12. #170705 13:50:49 server id 3656  end_log_pos 749 CRC32 0xcdb5c9d7     Xid = 107

13. COMMIT/*!*/;

从relay log中可以看到，主库上的更新操作在从库上是接收到了的。接着根据 show slave status\G的信息，也可以确定该事务是被sql线程应用了的。再仔细一看这个 relay log 发现，这个 update 操作是被以STATEMENT的格式保存下来，并复制到从库。所以在从库上只是简单的执行这个语句。并且因为从库上int_b=1的记录已经被修改为 int_b=2，从而在从库上执行这个语句的时候，找不到符合相应条件的记录需要修改。 这个更新操作是执行了的，只是没有找到符合where条件的记录。所以 show slave status\G 查看复制状态也是正常。但是主从数据不一致了。 所以，在复制架构中一定要强调不要随便在从库上执行insert、update、delete等操作，因为极有可能做了相应的操作之后，主从数据不一致，复制状态正常。应用查询数据出现异常，问题很难排查。

| 案例二：主从版本不一致导致的复制错误

环境信息

• 操作系统 Red Hat 6.7

• 数据库信息 

• 主库IP：192.168.1.36 

• 从库IP：192.168.1.57 

• 主库数据库版本：5.6.36 

• 从库数据库版本：5.7.18

• 数据库参数配置 sync_binlog=1 传统复制，即非GTID复制

故障重现

• 主从搭建复制架构，搭建步骤此处省略

• 在主库（192.168.1.36）上创建测试表

1. mysql> create database gangshen;

2. Query OK, 1 row affected (0.02 sec)

3. mysql> use gangshen

4. Database changed

5. mysql> create table tt(

6.    -> id int,

7.    -> name varchar(20),

8.    -> primary key(id,name));

9. Query OK, 0 rows affected (0.09 sec)

10. mysql> show create table tt;

11. +-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+

12. | Table | Create Table                                                                                                                                                          |

13. +-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+

14. | tt    | CREATE TABLE `tt` (

15.  `id` int(11) NOT NULL DEFAULT '0',

16.  `name` varchar(20) NOT NULL DEFAULT '',

17.  PRIMARY KEY (`id`,`name`)

18. ) ENGINE=InnoDB DEFAULT CHARSET=latin1 |

19. +-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+

20. 1 row in set (0.00 sec)

• 在从库（192.168.1.57）上检查数据以及复制状态

1. mysql> use gangshen;

2. Reading table information for completion of table and column names

3. You can turn off this feature to get a quicker startup with -A

4. Database changed

5. mysql> show create table tt;

6. +-------+------------------------------------------------------------------------------------------------------------------------------------------------+

7. | Table | Create Table                                                                                                                                   |

8. +-------+------------------------------------------------------------------------------------------------------------------------------------------------+

9. | tt    | CREATE TABLE `tt` (

10.  `id` int(11) NOT NULL,

11.  `name` varchar(20) NOT NULL,

12.  PRIMARY KEY (`id`,`name`)

13. ) ENGINE=InnoDB DEFAULT CHARSET=latin1 |

14. +-------+------------------------------------------------------------------------------------------------------------------------------------------------+

15. 1 row in set (0.00 sec)

16. mysql> show slave status\G

17. *************************** 1. row ***************************

18.              Master_Log_File: mysql-bin.000001

19.          Read_Master_Log_Pos: 372

20.               Relay_Log_File: mysql-relay-bin.000002

21.                Relay_Log_Pos: 569

22.        Relay_Master_Log_File: mysql-bin.000001

23.             Slave_IO_Running: Yes

24.            Slave_SQL_Running: Yes

25.          Exec_Master_Log_Pos: 372

26.              Relay_Log_Space: 776

27.            .......................................部分信息省略

28.        Seconds_Behind_Master: 0

29.                Last_IO_Errno: 0

30.                Last_IO_Error:

31.               Last_SQL_Errno: 0

32.               Last_SQL_Error:

33.  Replicate_Ignore_Server_Ids:

34.             Master_Server_Id: 3656

35.                  Master_UUID: b9e1f845-5d32-11e7-b7eb-fa163ea44438

36.             Master_Info_File: mysql.slave_master_info

37.                    SQL_Delay: 0

38.          SQL_Remaining_Delay: NULL

39.      Slave_SQL_Running_State: Slave has read all relay log; waiting for more updates

40.           Master_Retry_Count: 86400

41.           Retrieved_Gtid_Set:

42.            Executed_Gtid_Set:

43.                Auto_Position: 0

44. 1 row in set (0.00 sec)

• 在主库（192.168.1.36）上将id字段指定为允许为空

1. mysql> alter table tt modify column id int null;

2. Query OK, 0 rows affected (0.03 sec)

3. Records: 0  Duplicates: 0  Warnings: 0

4. mysql> show create table tt;

5. +-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+

6. | Table | Create Table                                                                                                                                                          |

7. +-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+

8. | tt    | CREATE TABLE `tt` (

9.  `id` int(11) NOT NULL DEFAULT '0',

10.  `name` varchar(20) NOT NULL DEFAULT '',

11.  PRIMARY KEY (`id`,`name`)

12. ) ENGINE=InnoDB DEFAULT CHARSET=latin1 |

13. +-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------+

14. 1 row in set (0.00 sec)

• 在从库（192.168.1.57）上检查复制状态，发现SQL线程报了1171的复制错误。

1. mysql> show create table tt;

2. +-------+------------------------------------------------------------------------------------------------------------------------------------------------+

3. | Table | Create Table                                                                                                                                   |

4. +-------+------------------------------------------------------------------------------------------------------------------------------------------------+

5. | tt    | CREATE TABLE `tt` (

6.  `id` int(11) NOT NULL,

7.  `name` varchar(20) NOT NULL,

8.  PRIMARY KEY (`id`,`name`)

9. ) ENGINE=InnoDB DEFAULT CHARSET=latin1 |

10. +-------+------------------------------------------------------------------------------------------------------------------------------------------------+

11. 1 row in set (0.00 sec)

12. mysql> show slave status\G

13. *************************** 1. row ***************************

14.              Master_Log_File: mysql-bin.000001

15.          Read_Master_Log_Pos: 494

16.               Relay_Log_File: mysql-relay-bin.000002

17.                Relay_Log_Pos: 569

18.        Relay_Master_Log_File: mysql-bin.000001

19.             Slave_IO_Running: Yes

20.            Slave_SQL_Running: No

21.            .......................................部分信息省略

22.                   Last_Errno: 1171

23.                   Last_Error: Error 'All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead' on query. Default database: 'gangshen'. Query: 'alter table tt modify column id int null'

24.                 Skip_Counter: 0

25.          Exec_Master_Log_Pos: 372

26.        Seconds_Behind_Master: NULL

27.                Last_IO_Errno: 0

28.                Last_IO_Error:

29.               Last_SQL_Errno: 1171

30.               Last_SQL_Error: Error 'All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead' on query. Default database: 'gangshen'. Query: 'alter table tt modify column id int null'

31.  Replicate_Ignore_Server_Ids:

32.             Master_Server_Id: 3656

33.                  Master_UUID: b9e1f845-5d32-11e7-b7eb-fa163ea44438

34.             Master_Info_File: mysql.slave_master_info

35.      Last_IO_Error_Timestamp:

36.     Last_SQL_Error_Timestamp: 170705 14:39:41

37.                Auto_Position: 0

38. 1 row in set (0.00 sec)

现象

从以上测试步骤中可以看到，在复制正常的情况下，主库上执行DDL提示没有错误，在从库上执行会有一个错误，提示说主键的字段必须非空，如果你要在一个索引中使用NULL属性，那应该使用唯一索引替代主键索引使用。

故障分析

因为主库为5.6.36版本，从库为5.7.18版本，所以很容易考虑说是不是因为主从数据库版本不一致的原因。但是具体是因为5.6和5.7中什么的不同导致的问题，需要接着分析。 可看到我们在主库上执行DDL的语句的时候，执行成功了，但是查看 show create table tt; 语句，可以看到这个DDL语句并没有起作用，所以这个DDL语句在5.6版本中是被忽略了。 我们直接拿这个DDL语句在5.7的数据库上执行，直接就报错了

1. mysql> use gangshen

2. Reading table information for completion of table and column names

3. You can turn off this feature to get a quicker startup with -A

4. Database changed

5. mysql> alter table tt modify column id int null;

6. ERROR 1171 (42000): All parts of a PRIMARY KEY must be NOT NULL; if you need NULL in a key, use UNIQUE instead

检查主库上的binlog日志以及从库上的relay log，都能看到DDL语句是被记录了的

1. # at 569

2. #170705 14:39:37 server id 3656  end_log_pos 494 CRC32 0x9de05dcd     Query   thread_id=11    exec_time=0 error_code=0

3. SET TIMESTAMP=1499236777/*!*/;

4. alter table tt modify column id int null

5. /*!*/;

可以说明这句DDL语句是被正常复制的，但是该语句在5.6主库上执行的时候，操作被忽略了。DDL语句被复制到5.7从库上执行的时候，因为5.7不允许该操作，所以SQL线程在重放该操作的时候报错，导致SQL线程中断。

| 作者简介

沈 刚·沃趣科技数据库技术专家

熟悉MySQL数据库运行机制，丰富的数据库及复制架构故障诊断、性能调优、数据库备份恢复及迁移经验。

点击查看招聘信息

相关链接

更多干货，欢迎来撩~