MySQL复制错误ERROR 1837的相关缺陷案例

之前的几篇文章中，介绍过MySQL主从复制以及一些常见的复制报错问题：

开启GTID主从同步出现1236错误问题解决字符集不同引起的主从同步异常1677报错问题

下面是又一例主从复制报错问题，ERROR 1837

复制报错

主从gtid报错，复制错误1837,这个复制故障可以说是第一次遇到。

代码语言：javascript复制

Last_Errno: 1837  
Last_Error: Error 'When @@SESSION.GTID_NEXT is set to a GTID, you must explicitly set it to a different value after a COMMIT or ROLLBACK. Please check GTID_NEXT variable manual page for detailed explanation. Current @@SESSION.GTID_NEXT is '2a46b388-5469-11e6-b949-845b123e2eff:64734471'.' on query. Default database: 'fander'. Query: 'delete from t_fander'

从官方文档的中“gtid的限制”《https://dev.mysql.com/doc/refman/5.6/en/replication-gtids-restrictions.html》的描述中，使用GTID复制有如下的限制：

CREATE TABLE … SELECT statements CREATE TEMPORARY TABLE statements inside transactions Transactions or statements that update both transactional and nontransactional tables.

复制报错可能的原因

1、涉及非事务性存储引擎的更新。例如，myisam引擎表，主库执行insert delayed into xxx values…

2、enforce_gtid_consistency为OFF，CREATE TABLE … SELECT语句。

3、主从引擎不一致，主库innodb引擎一个事务中写入两条数据，传到从库的myisam引擎执行这个事务

4、临时表

5、较早之前的一些bug

报错可能原因的分析

1、检查过所有表都是innodb表，没有myisam表，故排除。

代码语言：javascript复制

mysql> select table_schema,table_name,engine from information_schema.tables where engine !='innodb' and table_schema not in ('mysql','information_schema','performance_schema');
Empty set (0.00 sec)

2、事实上检查过enforce_gtid_consistency主从库都为on，CREATE TABLE … SELECT语句不能执行成功，并且这次故障并不涉及CREATE TABLE … SELECT语句，故排除。

代码语言：javascript复制

mysql> create table t7 select * from t6;
ERROR 1786 (HY000): CREATE TABLE ... SELECT is forbidden when @@GLOBAL.ENFORCE_GTID_CONSISTENCY = 1.

3、由于这个case是第一次发生了，之前才重做过从库，所以不存在主从不一致引擎的可能，并且第1步分析也知道库里并没有myisam表，故排除。

4、没有涉及临时表

5、查阅了这些bug在5.6.9和5.6.7上分别修复了。我们目前MySQL版本为5.6.23

下面就根据报错信息的提示，来解析一下binlog探个究竟吧！

报错排查

从1837报错的英文信息描述上，我们得出以下信息:

发生故障的gtid号是2a46b388-5469-11e6-b949-845b123e2eff:64734471
发生故障的sql为delete from t_fander，或前后。
提示信息:设置为GTID时，您必须在提交或回滚之后显式地将其设置为不同的值

备注：出于信息安全考虑，没有办法展示原始的binlog。

在解析了主从两个数据库的binlog后，发现从库大概是在执行以下sql时出了问题:

主库:

代码语言：javascript复制

begin;
use fander;update t1,t2,t3,(select * from (select * from t4)d)d set t1.a='123';
use fander;delete from t5;
use fander;delete from t6;
commit;

原update的sql比这个复杂得多，有where条件的，请不要纠结我这个sql为什么没事关联那么多张表。。。

主库上着3条DML操作是同一个事务，但在从库回放时，发生了事务的拆分。变成如下的样子：

从库:

代码语言：javascript复制

begin;
use fander;update t1,t2,t3,(select * from (select * from t4)d)d set t1.a='123';
commit; 
#从库解析时，无端端给加了一个commit。
use fander;delete from t5; 
#这条在从库binlog里并没有。也就是上面commit后，正常需要设置不同的@@SESSION.GTID_NEXT，但他没有设置，所以报复制错误了。事务发生了异常拆分了！！

问题重现

主库上操作:

代码语言：javascript复制

vim /tmp/c.sql
begin;
#经过多次测试，update语句可以修改为这个更简单的语句
use fander;update t1,t2,t3,t4 set t1.a='123';
use fander;delete from t5;
use fander;delete from t6;
commit;
mysql> create database fander;
mysql> set global  tx_isolation='Repeatable-Read';
mysql> set global  binlog_format='Mixed';
mysql> create table t1(a int);
mysql> create table t2(a int);
mysql> create table t3(a int);
mysql> create table t4(a int);
mysql> create table t5(a int);
mysql> create table t6(a int);
mysql> flush logs;
mysql> exit
mysql> source /tmp/c.sql

解析binlog记录如下所示：

代码语言：javascript复制

SET @@SESSION.GTID_NEXT= '316d072f-9633-11e8-b0f3-000c294a5f55:16719'/*!*/;
# at 1588
#180815 21:51:29 server id 897905305  end_log_pos 1672 CRC32 0xbf36600e         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
BEGIN
/*!*/;
# at 1672
#180815 21:51:29 server id 897905305  end_log_pos 1784 CRC32 0xdc2d6070         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
update t1,t2,t3,t4 set t1.a='123'
/*!*/;
# at 1784
#180815 21:51:29 server id 897905305  end_log_pos 1869 CRC32 0x931ab661         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
COMMIT   <<<-----被额外添加的commit----------
/*!*/;
# at 1869
#180815 21:51:29 server id 897905305  end_log_pos 1917 CRC32 0x116a4cfb         GTID [commit=yes]
SET @@SESSION.GTID_NEXT= '316d072f-9633-11e8-b0f3-000c294a5f55:16720'/*!*/;
# at 1917
#180815 21:51:29 server id 897905305  end_log_pos 1992 CRC32 0x6fe6ccaa         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
BEGIN
/*!*/;
# at 1992
#180815 21:51:29 server id 897905305  end_log_pos 2076 CRC32 0x0695b437         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
delete from t5
/*!*/;
# at 2076
#180815 21:51:29 server id 897905305  end_log_pos 2160 CRC32 0x56083744         Query   thread_id=7176  exec_time=0     error_code=0
SET TIMESTAMP=1534341089/*!*/;
delete from t6
/*!*/;
# at 2160
#180815 21:51:29 server id 897905305  end_log_pos 2191 CRC32 0xfe7fe294         Xid = 31066
COMMIT/*!*/;

测试结果说明

数据库版本

MySQL5.6.23

参数说明：

tx_isolation=’Repeatable-Read’;
binlog_format=’Mixed’;
autocommit=1；

解析结果:

多表关联update操作后，事务就被拆分了。

事务被拆分，这现象不正常啊？下面测试是否BUG。在参数配置不变的情况下，在5.7版本（5.7.21）的实例再来一次测试一下：

测试步骤和上面的一样。解析binlog的结果如下：

代码语言：javascript复制

BEGIN
/*!*/;
# at 303
#180816 15:01:12 server id 352148329  end_log_pos 415 CRC32 0xe61e4415  Query thread_id=1477446 exec_time=0 e
rror_code=0
use `fander`/*!*/;
SET TIMESTAMP=1534402872/*!*/;
update t1,t2,t3,t4 set t1.a='123'
/*!*/;
# at 415
#180816 15:01:12 server id 352148329  end_log_pos 499 CRC32 0xd51c509c  Query thread_id=1477446 exec_time=0 e
rror_code=0
SET TIMESTAMP=1534402872/*!*/;
delete from t5
/*!*/;
# at 499
#180816 15:01:12 server id 352148329  end_log_pos 583 CRC32 0x17e3871d  Query thread_id=1477446 exec_time=0 e
rror_code=0
SET TIMESTAMP=1534402872/*!*/;
delete from t6
/*!*/;
# at 583
#180816 15:01:12 server id 352148329  end_log_pos 614 CRC32 0x59f429aa  Xid = 44831936
COMMIT/*!*/;
SET @@SESSION.GTID_NEXT= 'AUTOMATIC' /* added by mysqlbinlog */ /*!*/;
DELIMITER ;
# End of log file
/*!50003 SET COMPLETION_TYPE=@OLD_COMPLETION_TYPE*/;
/*!50530 SET @@SESSION.PSEUDO_SLAVE_MODE=0*/;

测试结果:

数据库版本:

MySQL5.7.21

参数说明:

tx_isolation=’Repeatable-Read’;
binlog_format=’Mixed’;
autocommit=1；

解析结果:

可以看出update和delete之间并没有自动添加commit，没有自动拆分事务。

复制BUG确认

在查阅mysql bug库后，发现这个是一个已知bug《https://bugs.mysql.com/bug.php?id=71695》，并已经在5.6.27上修复了。

Replication: If statement based logging was in use, when updating multiple tables in a single statement, a single transaction could be logged as two different transactions. This was due to the binary logging process not properly identifying statements which were operating over transactional tables. The fix ensures that they are correctly identified, even if such statements do not change the contents of the tables. (Bug #16621582, Bug #21349028)

解决方法

避免不正确的拆事务的发生。

方案一: 开发修改sql。这个方案可以说是第一个排除的。因为只能解决这次问题，并不能从根本上解决。方案二：升级MYSQL的版本。升级5.7.21是可行的。方案三: 修改binlog格式。从bug的描述可知，此问题只出现在基于语句的日志记录，所以binlog_format修改为row格式可以解决这个问题。方案四: 修改事务隔离级别。而修改事务隔离级别是有风险的，尤其是涉及金钱交易，这个需要先与开发一同测试后方能修改。

经过选择和测试，方案三解决了这次的问题。