双主master-master复制Err 1677故障分析

江南才子

　　一、报错信息近期项目实施同事对系统升级，对test.test_tab_t1的某个字段进行变更，SQL语句如下：ALTER TABLE TEST.TEST_TAB_T1 MODIFY BXXX VARCHAR(200);在该项目项目在做系统升级之后，出现MySQL主从同步报错，报错信息如下：

mysql>show slave status\G
      Master_Log_File: binlog.000233
  Read_Master_Log_Pos: 274415020
       Relay_Log_File: relay-bin.000253
        Relay_Log_Pos: 175535154
Relay_Master_Log_File: binlog.000233
     Slave_IO_Running: Yes
    Slave_SQL_Running: No
    .................: 
           Last_Errno: 1677
           Last_Error: Column 28 of table 'test.test_tab_t1' cannot be converted from type 'varchar(30)(bytes))' to type 'varchar(400(bytes) gbk)'
         Skip_Counter: 0
  Exec_Master_Log_Pos: 175536357
      Relay_Log_Space: 274410464

MySQL告警日志的报错信息：          

2020-03-24T16:53:16.051244Z 11686 [ERROR] Slave SQL for channel '': Column 28 of table 'test.test_tab_t1' cannot be converted from type 'varchar(30(bytes))' to type 'varchar(400(bytes) gbk)', Error_code: 1677
2020-03-24T16:53:16.051269Z 11686 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'binlog.000233' position 175536357.

二、环境信息 该项目目前使用的mysql社区版5.7.24，字符集为：gbk，binlog是ROW格式，采用的是keepalived+双主（master-master）的架构。

mysql>select @@version,@@character_set_server,@@binlog_format;
+-----------+------------------------+-----------------+
| @@version | @@character_set_server | @@binlog_format |
+-----------+------------------------+-----------------+
| 5.7.24   | gbk             | ROW             |
+-----------+------------------------+-----------------+

三、诊断过程1、根据MySQL Replication Breaks With Error 1677: Column .. of Table '...' Cannot Be Converted (Doc ID 2037712.1)文档来看报错信息err1677分析来看test.test_tab_t1表的某个列(Column 28),出现了字符集相关的转换错误。 首先对比（master1-master2）的字符集设置信息：
之后对比（master1-master2）库级，表级，列级的字符集信息：MASTER1 库级，表级，列级的字符集信息:

mysql>select  from information_schema.schemata where schema_name='test';
+--------------+-------------+----------------------------+------------------------+----------+--------------------+
| CATALOG_NAME | SCHEMA_NAME | DEFAULT_CHARACTER_SET_NAME | DEFAULT_COLLATION_NAME | SQL_PATH | DEFAULT_ENCRYPTION |
+--------------+-------------+----------------------------+------------------------+----------+--------------------+
| def    | test    | gbk             | gbk_general_ci    |   NULL | NO           |
+--------------+-------------+----------------------------+------------------------+----------+--------------------+
mysql>select table_schema,table_name,table_type,table_collation from information_schema.tables  where table_name='test_tab_t1';
+--------------+------------+------------+-----------------+
| TABLE_SCHEMA | TABLE_NAME | TABLE_TYPE | TABLE_COLLATION |
+--------------+------------+------------+-----------------+
| test    | test_tab_t1| BASE TABLE | gbk_chinese_ci |
+--------------+------------+------------+-----------------+
mysql>select table_name,column_name,character_maximum_length,character_octet_length,character_set_name,collation_name 
from information_schema.columns where table_name='test_tab_t1' and table_schema='test' and ordinal_position=29;
+------------+-------------+--------------------------+------------------------+--------------------+----------------+
| TABLE_NAME | COLUMN_NAME | CHARACTER_MAXIMUM_LENGTH | CHARACTER_OCTET_LENGTH | CHARACTER_SET_NAME | COLLATION_NAME |
+------------+-------------+--------------------------+------------------------+--------------------+----------------+
| test_tab_t1| BXXX     |               200 |              400  | gbk            | gbk_chinese_ci |
+------------+-------------+--------------------------+------------------------+--------------------+----------------+

MASTER2 库级，表级，列级的字符集信息:

mysql>select  from information_schema.schemata where schema_name='test';
+--------------+-------------+----------------------------+------------------------+----------+--------------------+
| CATALOG_NAME | SCHEMA_NAME | DEFAULT_CHARACTER_SET_NAME | DEFAULT_COLLATION_NAME | SQL_PATH | DEFAULT_ENCRYPTION |
+--------------+-------------+----------------------------+------------------------+----------+--------------------+
| def       | test     | gbk                | gbk_general_ci      |   NULL | NO           |
+--------------+-------------+----------------------------+------------------------+----------+--------------------+
mysql>select table_schema,table_name,table_type,table_collation from information_schema.tables  where table_name='test_tab_t1';
+--------------+------------+------------+-----------------+
| TABLE_SCHEMA | TABLE_NAME | TABLE_TYPE | TABLE_COLLATION |
+--------------+------------+------------+-----------------+
| test      | test_tab_t1| BASE TABLE | gbk_chinese_ci |
+--------------+------------+------------+-----------------+
mysql>select table_name,column_name,character_maximum_length,character_octet_length,character_set_name,collation_name 
from information_schema.columns where table_name='test_tab_t1' and table_schema='test' and ordinal_position=29;
+------------+-------------+--------------------------+------------------------+--------------------+----------------+
| TABLE_NAME | COLUMN_NAME | CHARACTER_MAXIMUM_LENGTH | CHARACTER_OCTET_LENGTH | CHARACTER_SET_NAME | COLLATION_NAME |
+------------+-------------+--------------------------+------------------------+--------------------+----------------+
| test_tab_t1| BXXX   |           200 |         400 | gbk        | gbk_chinese_ci |
+------------+-------------+--------------------------+------------------------+--------------------+----------------+

根据文档（(Doc ID 2037712.1）来看确实是系统升级变更表字段所对应的列（ALTER TABLE TEST.TEST_TAB_T1 MODIFY BXXX VARCHAR(200);）出现了问题。报错：Last_Error: Column 28 of table 'test.test_tab_t1' cannot be converted from type 'varchar(30(bytes))' to type 'varchar(400(bytes) gbk)就是test.test_tab_t1表变更的字段bxxx（ordinal_position=29）在复制过程中出现了字符集问题，gbk的字节大小是2，变更前bxxx确实是varchar(15)。

mysql> select * from information_schema.character_sets where character_set_name='gbk';
+--------------------+----------------------+------------------------+--------+
| CHARACTER_SET_NAME | DEFAULT_COLLATE_NAME | DESCRIPTION        | MAXLEN |
+--------------------+----------------------+------------------------+--------+
| gbk           | gbk_chinese_ci     | GBK Simplified Chinese |    2 |
+--------------------+----------------------+------------------------+--------+

但对比了（master1-master2）库级，表级，列级的字符集信息是一致的，不存在字符集不一致的问题。这时感觉问题没那么简单，接着往下分析。我一开始想着是否是我们实施人员没按规范来操作，因为是双主环境，是否是在两个实例同时执行了这个语句，排错过程中发现/etc/my.cnf的client里面character_set_client设置master1上是utf8，master2上是gbk。所以我们来看看发生故障的时间点binlog里面的信息，报错是在binlog.000233，position为175536357时停止的。

mysqlbinlog --no-defaults --start-position=175536357 --database=test  /opt/mysql/log/binlog/binlog.000233 --verbose at 175536357200325  0:53:16 server id 1  end_log_pos 175536422 CRC32 0xddd5d37 Anonymous_GTID  last_committed=271185   sequence_number=27186  rbr_only=yes
/!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED//*!/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/!*/; at 175536422200325  0:53:16 server id 1  end_log_pos 175536505 CRC32 0x3799f3b Query   thread_id=14154792  exec_time=0   error_code=0
SET TIMESTAMP=1585068796/!/;
SET @@session.pseudo_thread_id=14154792/*!/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=0, @@session.unique_checks=1, @@session.autocommit=1/!*/;
SET @@session.sql_mode=1075838976/!/;
SET @@session.auto_increment_increment=2, @@session.auto_increment_offset=2/*!/;
/!\C gbk *//!/;
SET @@session.character_set_client=28,@@session.collation_connection=28,@@session.collation_server=28/*!/;
SET @@session.lc_time_names=0/!*/;
SET @@session.collation_database=DEFAULT/!/;
BEGIN
/*!/; at 175536505200325  0:53:16 server id 1  end_log_pos 175536685 CRC32 0xe3db6b6b    Table_map: test.test_tab_t1 mapped to number 23434 at 175536685200325  0:53:16 server id 1  end_log_pos 175537481 CRC32 0xf1343123    Update_rows: table id 2334 flags: STMT_END_F UPDATE test.test_tab_t1 WHERE   @1='........'   ..........   @29='........'   ..........   @40='...' SET   @1='........'   ..........   @29='........'   ..........   @40='...'

看到binlog里面的SET @@session.character_set_client=28,@@session.collation_connection=28,@@session.collation_server=28 字符集确实是GBK

mysql> select  from information_schema.collations where id=28;
+----------------+--------------------+----+------------+-------------+---------+---------------+
| COLLATION_NAME | CHARACTER_SET_NAME | ID | IS_DEFAULT | IS_COMPILED | SORTLEN | PAD_ATTRIBUTE |
+----------------+--------------------+----+------------+-------------+---------+---------------+
| gbk_chinese_ci | gbk       | 28 | Yes     | Yes      |     1 | PAD SPACE   |
+----------------+--------------------+----+------------+-------------+---------+---------------+
1 row in set (0.01 sec)

以上足以肯定不是字符集不一致的情况导致。所以使用官方推荐的方法,设置参数slave_type_conversions=ALL_LOSSY/ALL_NON_LOSSY来解决是无效的，而且该方法还存在数据转换丢失的风险。另外根据https://bugs.mysql.com/bug.php?id=83461也描述了某个字段字符集不一致的主从复制报err1677错误的问题，同时还提到另外一个情况，binlog_format=ROW时，因为解析中继日志时出现解析问题，可以考虑把binlog_format=MIXED格式，尝试拉起slave也是无法拉起的。分析到这，感觉没有了思路，继续查找资料吧，有时就这样，山穷水复疑无路，柳暗花明又一村。终于找到一个很有代表性的参考资料：https://bugs.mysql.com/bug.php?id=88595，这个是在5.6.37上的Bug #88595，Row-based master-master replication broken by add column or drop column。但该项目的环境是5.7.24，架构都是binlog_format=ROW的双主。
通过以上信息对比我贴出的binlog信息，确实中断的时间点存在update test.test_tab_t1表的情况。这里就说的通，虽然版本不一致，但根据故障现象是几乎接近的。ALGORITHM=INPLACE (Default)情况下:master1执行了：ALTER TABLE TEST.TEST_TAB_T1 MODIFY BXXX VARCHAR(200);按记录在binlog里，master2通过拉取binlog进行同步变更字段信息的语句，在运行过程中，master2同时存在update test.test_tab_t1表的情况(比变更的字段语句先完成)master1在进行同步update  test.test_tab_t1表的语句时，因为已经变更了字段，表结构发生了变化，而update语句还是原结构的信息，所以就出现了err1677的报错 。
以上基本说的通了，不过这里还有2个疑问，1个是这个业务不是配置的双写，只写其中一个实例，唯一可解释的就是，实施同事是在非写实例上(master1)进行的DDL动作。还有1个就是版本问题，后来也咨询了项目实施同事，该数据库是由5.6基础上升级而来。难到...？难到是升级后会有遗留问题？目前能力有限，先记录下来，后续再更深入分析。
四、解决办法 这里的解决方法对我这个情况来说没有参考性，而且经过上述分析，及根据该表的业务情况，决定先跳过该错误，后检验数据一致性。

stop slave; 
-- 表示跳过一步错误，后面的数字可变，1表示跳过1步
set global sql_slave_skip_counter = 1; 
start slave; pt-table-checksum可以用来检测master1-master2数据库test中的test_tab_t1表的数据一致性，如果存在不一致在使用该工具进行修复。
pt-table-checksum --nocheck-replication-filters --databases=test --replicate=test.test_tab_t1 --create-replicate-table --host=xxx --port 3306 -uroot -pxxx

五、故障总结
以上的故障分析和解决故障的过程，发现的这个BUG，让我觉得这个跟oracle goldengate只复制DML，源端表进行了DDL变更的OGG-01161及OGG-01163很相似。网上很多OGG-01161，OGG-01163源端表结构发生变化导致replicat进程abend的文章，都提到对比源端和目标端的表结构一致，重启R进程还是报错。虽然源端和目标端该字段的长度已修改，且def文件也都已修改，但生成的trail文件中的meta信息并不会更新。replicat进程默认按照trail文件中的meta信息进行操作。所以还是报错。需要加OVERRIDE选项，新的def内容才能覆盖trail中的meta信息。所以这个故障案例也是类似的master2的update语句是在DDL变更前，同步到master1的表meta信息也是变更前的，而master1已经是表meta信息更后的结构了，所以就会出现该报错。真是万物都有相通性，数据库也不例外。