雙主master-master複製Err 1677故障分析

1、報錯信息

近期項目實施同事對系統升級，對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.

2、環境信息 

該項目目前使用的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             |
+-----------+------------------------+-----------------+

3、診斷過程

一、根據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 175536357
#200325  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 175536422
#200325  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 175536505
#200325  0:53:16 server id 1  end_log_pos 175536685 CRC32 0xe3db6b6b    Table_map: `test`.`test_tab_t1` mapped to number 23434
# at 175536685
#200325  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基礎上升級而來。難到...？難到是升級後會有遺留問題？目前能力有限，先記錄下來，後續再更深刻分析。

4、解決辦法

這裏的解決方法對我這個狀況來講沒有參考性，並且通過上述分析，及根據該表的業務狀況，決定先跳過該錯誤，後檢驗數據一致性。

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

5、故障總結

以上的故障分析和解決故障的過程，發現的這個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信息更後的結構了，因此就會出現該報錯。

真是萬物都有相通性，數據庫也不例外。