背景描述

案件回顾

  • 某著名保险企业邮件一条DTS链路故障，报错信息显示目标库的对应表不存在
  • 链路是整库同步，支持源库创建表后，目标库会同步创建表
  • 请我方协助排查原因并修复故障

先介绍一下数据表情况，因为涉及到内部真实的数据，所以表结构和日志都做了脱敏操作，但不会影响具体的分析。

信息详情

信息 内容
故障时间点 2020-05-20 10:33:50
DTS链路名称 Polardb 5.6->RDS for MySQL5.7
DTS同步失败报错内容 DTS-071001: the Table cds.plog Information Loaded failed in Target DB. cause by [com.mysql.jdbc.exceptions.jdbc4.MySQLSyntaxErrorException:Table ‘cds.plog’ doesn’t exist] About more information in [https://yq.aliyun.com/articles/505378].
同步粒度 整库同步
源数据库名称 PDB
源数据库类型 PolarDB for MySQL 5.6
源库同步用户/权限 i_read/只读
目标数据库名称 RDS
目标数据库类型 RDS for MySQL 5.7
目标库同步用户/权限 e_dev/读写

排障过程

阶段一：怀疑人为因素造成

  • 解析故障时间段源目标库的 binlog 来验证
  • 下载目标数据库对应时间段的binlog → mysql-bin.000498，并通过mysqlbinlog -vv 的方式对日志进行解析

目标库 binlog 解析结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
COMMIT/*!*/;
# at 8993767
#200520 10:30:11 server id 2278327273  end_log_pos 8993832 CRC32 0xeb1056ff     GTID    last_committed=2005     sequence_number=2006    rbr_only=no
SET @@SESSION.GTID_NEXT= '9669d21f-7e11-11ea-bdd0-6c92bf5c9bf2:6704774'/*!*/;
# at 8993832
#200520 10:30:11 server id 2278327273  end_log_pos 8993973 CRC32 0xa980631b     Query   thread_id=1653742       exec_time=0     error_code=0
use `cloudods`/*!*/;
SET TIMESTAMP=1589941811/*!*/;
SET @@session.foreign_key_checks=0/*!*/;
SET @@session.sql_mode=0/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=33/*!*/;
DROP TABLE IF EXISTS `plog` /* generated by server */
/*!*/;
# at 8993973
#200520 10:30:20 server id 2278327273  end_log_pos 8994038 CRC32 0x9b7bb805     GTID    last_committed=2006     sequence_number=2007    rbr_only=yes
/*!50718 SET TRANSACTION ISOLATION LEVEL READ COMMITTED*//*!*/;
SET @@SESSION.GTID_NEXT= '9669d21f-7e11-11ea-bdd0-6c92bf5c9bf2:6704775'/*!*/;
# at 8994038
#200520 10:30:20 server id 2278327273  end_log_pos 8994106 CRC32 0x84aeabab     Query   thread_id=1273498       exec_time=0     error_code=0
SET TIMESTAMP=1589941820/*!*/;
BEGIN
/*!*/;
# at 8994106
#200520 10:30:20 server id 2278327273  end_log_pos 8994276 CRC32 0x5d226504     Table_map: `is`.`sys_userinfo` mapped to number 1362
# at 8994276
#200520 10:30:20 server id 2278327273  end_log_pos 8994893 CRC32 0x43a6caee     Delete_rows: table id 1362 flags: STMT_END_F
 
BINLOG '
PJbEXhPpg8yHqgAAAOQ9iQAAAFIFAAAAAAEADGlzcF9tYWluZGJfcwAMc3lzX3VzZXJpbmZvACoI
Dw8PDw8PDw8PDw8SDw8DAwMDDxISCPwSAw8PEhIPDw8SEg8PDw8PDw89YAADAAMA7gIwADAANgAY
AFgCYABgAAADAIABAwAAAAIAlgBgAAAA/QJYAlgCAAAeAP0C/QL9Av0CPAADAP7/////AwRlIl0=
PJbEXhnpg8yHaQIAAE1AiQAAAFIFAAAAAAMAKv///////8BYAACA/LEIAAAAAAAACTAwMDAxNjk3
MQFBATEhAOacseWLpOWNjiAgICAgICAgICAgICAgICAgICAgICAgIAROVUxMBDA5ODYEAEZFMDEJ
RzAwMDAwNDA5ATABAAAAAQAAAAEAAAABAAAAAUGZpG4AAJmknQSyAAAAAAAAAADKAHtBU0lUVTpD
TSxFQUZDUjowMDAwMDM0MjEsQ0hBTk5FTDpBZ2VuY3l9LXsiQUdUQ09EIjoiMDAwMDE2OTcxICAg
ICIsIk9GRkNPRCI6IkZFMDEiLCJBR1lDT0QiOiJHMDAwMDA0MDkiLCJyb3dfbnVtYmVyIjo5NSwi
Q09OVFlQRSI6Ik0xIiwiaW5pUHdkIjoiMTExMTExMTEiLCJBR1ROQU1FIjoi5pyx5Yuk5Y2OICAg
ICAgICAgICAgICAgICAgICAgICAgIn2ZpgcaagAAAAAGQWdlbmN5CDExMDMwNTM3mZ3lBKiZpmil
lAIAQ00IADExMTExMTExGABSWU96dm9Vd3JiaEJBeWwxNnhxLzRRPT2ZpmimRpmmaKZGA0lTUEwA
MDdFNDAwMDUwMDE0MDAwQTAwMTYwMDE2MEI4MEYyNDAwMDAwMDAxRDAwMDBBRkI0MDAwMDM0MUEw
MDA2MDAwMDAwMDEwMDAwMDAwMCIAOTIwMDAwMDA0MzQ4NEY1NDMzNTIzODQzNTM1MTRDMzEzMRQA
MDAwMEFGQjQwMDAwMzQxQTAwMDYUMjAyMDA1MjAxMDIyMjIxOTMwMDABSe7KpkM=
'/*!*/;
### DELETE FROM `isp_maindb_s`.`sys_userinfo`
### WHERE
###   @1=2225 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='000016971' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
###   @3='A' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @4='1' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */

发现SQL：DROP TABLE IF EXISTS plog /* generated by server */

执行时间：200520 10:30:11

由于该DROP动作，无论库中是否存在该表，binlog均会记录，因此想何时该DROP动作在建表之后

从源库information_schema.tables获取表的创建时间

与DROP的时间一致

因后来证实，当 alter 表时，create_time 字段会被更新；增删改查表时，update_time字段会被更新；truncate表时，时间字段不被更新

因此怀疑该时间不够准确，决定从PolarDB获取对应时间段的binlog日志，查看该时间是否是CREATE TABLE的时间

由于PolarDB不支持直接下载binlog需要通过客户端连接的方式把binlog日志解析到本地

通过客户端连接获取binlog的命令

1
mysqlbinlog -vv -P 3306 -uxxxx -pxxxx -hxxxx.mysql.rds.aliyuncs.com --read-from-remote-server --start-datetime='2020-05-20 09:00:00' --stop-datetime='2020-05-20 11:00:00' --base64-output=DECODE-ROWS mysql-bin.000xxx > xxxlog.sql

遇到报错的情况下，需检查mysqlbinlog版本是否正确

源端数据库binlog内容

源库故障时间 binlog 解析结果

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
# at 398730036
#200520 10:30:10 server id 9793953  end_log_pos 398730084 CRC32 0x42791024      GTID    last_committed=0        sequence_number=0
SET @@SESSION.GTID_NEXT= 'e1ecc4a7-f9fa-11e9-ad35-506b4b478fa4:107546949'/*!*/;
# at 398730084
#200520 10:30:10 server id 9793953  end_log_pos 398730225 CRC32 0x28099038      Query   thread_id=1749351       exec_time=0     error_code=0
use `cloudods`/*!*/;
SET TIMESTAMP=1589941810/*!*/;
/*!\C utf8 *//*!*/;
SET @@session.character_set_client=33,@@session.collation_connection=33,@@session.collation_server=33/*!*/;
DROP TABLE IF EXISTS `plog` /* generated by server */
/*!*/;
# at 398730225
#200520 10:30:11 server id 9793953  end_log_pos 398730273 CRC32 0x699cf5ca      GTID    last_committed=0        sequence_number=0
SET @@SESSION.GTID_NEXT= 'e1ecc4a7-f9fa-11e9-ad35-506b4b478fa4:107546950'/*!*/;
# at 398730273
#200520 10:30:11 server id 9793953  end_log_pos 398731371 CRC32 0xe7281576      Query   thread_id=1749353       exec_time=0     error_code=0
SET TIMESTAMP=1589941811/*!*/;
/*!\C utf8mb4 *//*!*/;
SET @@session.character_set_client=45,@@session.collation_connection=45,@@session.collation_server=33/*!*/;
create table `cds`.`plog` (^M
  `co` varchar(4) collate utf8_bin not null default '',^M
  `polnum` varchar(10) collate utf8_bin not null default '',^M
  `code` varchar(5) collate utf8_bin default null,^M
  `msg` varchar(50) collate utf8_bin default null,^M
  `lstupdtime` datetime(6) default null,^M
  `dtl__capxrestart1` varchar(255) collate utf8_bin default null,^M
  `dtl__capxrestart2` varchar(255) collate utf8_bin default null,^M
  `dtl__capxuow` varchar(255) collate utf8_bin default null,^M
  `dtl__capxuser` varchar(255) collate utf8_bin default null,^M
  `dtl__capxtimestamp` varchar(20) collate utf8_bin default null,^M
  `dtl__capxaction` varchar(1) collate utf8_bin default null,^M
  `dtl__capxcasdelind` varchar(1) collate utf8_bin default null,^M
  `dtl__capxrrn` decimal(10,0) default null,^M
  `inserttime` timestamp  ,^M
  `updatetime` timestamp  ,^M
  `srcsys` varchar(10) collate utf8_bin default null,^M
  primary key (`co`,`polnum`,`lstupdtime`)^M
) engine=innodb default charset=utf8 collate=utf8_bin
/*!*/;
# at 398731371
#200520 10:30:19 server id 9793953  end_log_pos 398731419 CRC32 0x7bc1d5fb      GTID    last_committed=0        sequence_number=0
SET @@SESSION.GTID_NEXT= 'e1ecc4a7-f9fa-11e9-ad35-506b4b478fa4:107546951'/*!*/;
# at 398731419
#200520 10:30:19 server id 9793953  end_log_pos 398731487 CRC32 0xfbae67c6      Query   thread_id=452351        exec_time=0     error_code=0
SET TIMESTAMP=1589941819/*!*/;
BEGIN
/*!*/;
# at 398731487
#200520 10:30:19 server id 9793953  end_log_pos 398731657 CRC32 0xfc6068eb      Table_map: `is`.`sys_userinfo` mapped to number 1405
# at 398731657
#200520 10:30:19 server id 9793953  end_log_pos 398732274 CRC32 0x95cb0304      Delete_rows: table id 1405 flags: STMT_END_F
### DELETE FROM `isp_maindb_s`.`sys_userinfo`
### WHERE
###   @1=2225 /* LONGINT meta=0 nullable=0 is_null=0 */
###   @2='000016971' /* VARSTRING(96) meta=96 nullable=1 is_null=0 */
###   @3='A' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */
###   @4='1' /* VARSTRING(3) meta=3 nullable=1 is_null=0 */

获得如下发现：

  • 几乎相同的时间都有DROP TABLE的动作
  • 区别是源端有CREATE TABLE的记录，而目标端没有CREATE TABLE的记录

阶段二：怀疑DTS工具BUG

  • 由于阶段一获取的源库和目标库的 binlog 日志，推测是源库在建表的过程中，先进行了一个DROP TABLE IF EXISTS的动作，然后再CREATE TABLE

  • 而目标库只有DROP TABLE IF EXISTS，而缺失CREATE TABLE的记录，因此怀疑是DTS少传输了CREATE TABLE的部分

  • 向阿里方提工单协助解决此问题

阶段三：手动建表进行故障恢复

  • 由于目标端是缺失了对应的表，造成的故障，因此决定通过手动在目标端创建表来解决问题

  • 从源端SHOW CREATE TABLE获取建表语句

源端 SHOW CREATE TABLE

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
mysql>show create table plog\G
*************************** 1. row ***************************
       Table: plog
Create Table: CREATE TABLE `plog` (
  `co` varchar(4) COLLATE utf8_bin NOT NULL DEFAULT '',
  `polnum` varchar(10) COLLATE utf8_bin NOT NULL DEFAULT '',
  `code` varchar(5) COLLATE utf8_bin DEFAULT NULL,
  `msg` varchar(50) COLLATE utf8_bin DEFAULT NULL,
  `lstupdtime` datetime(6) NOT NULL DEFAULT '0000-00-00 00:00:00.000000',
  `dtl__capxrestart1` varchar(255) COLLATE utf8_bin DEFAULT NULL,
  `dtl__capxrestart2` varchar(255) COLLATE utf8_bin DEFAULT NULL,
  `dtl__capxuow` varchar(255) COLLATE utf8_bin DEFAULT NULL,
  `dtl__capxuser` varchar(255) COLLATE utf8_bin DEFAULT NULL,
  `dtl__capxtimestamp` varchar(20) COLLATE utf8_bin DEFAULT NULL,
  `dtl__capxaction` varchar(1) COLLATE utf8_bin DEFAULT NULL,
  `dtl__capxcasdelind` varchar(1) COLLATE utf8_bin DEFAULT NULL,
  `dtl__capxrrn` decimal(10,0) DEFAULT NULL,
  `inserttime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
  `updatetime` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00',
  `srcsys` varchar(10) COLLATE utf8_bin DEFAULT NULL,
  PRIMARY KEY (`co`,`polnum`,`lstupdtime`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin
返回行数：[1]，耗时：6 ms.

将该建表语句复制到目标端手动创建，然后启动DTS链路

再通过SELECT * FROM 表 来验证数据是否正常同步过来时，提示该表不存在

刷新DTS链路信息，DTS链路报错，报错与之前一致

多次重复上述操作，均可复现，现象反馈给阿里方，协助排查该问题

阶段四：开启审计，查找“真凶”

  • 在阿里方的建议下，开启审计，查看是“谁”删除了这张表

审计内容

发现是eds_dev用户，是 DTS 同步用户，传输过来的动作是先进行 DROP 再进行创建，但创建失败

CREATE 之前先 DROP，就是手动创建被会失败的原因

而 CREATE 之所以失败，根据审计的提示，失败代码：1171

查询 MySQL 的错误代码 1171

当主键的字段属性为“允许空值”时会报出1171的错误代码

检查审计 CREATE TABLE 语句

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
---目标库 CREATE TABLE 语句---
create table `cds`.`plog`
( `co` varchar(4) collate utf8_bin not null default '',
`polnum` varchar(10) collate utf8_bin not null default '',
`code` varchar(5) collate utf8_bin default null,
`msg` varchar(50) collate utf8_bin default null,
`lstupdtime` datetime(6) default null,
`dtl__capxrestart1` varchar(255) collate utf8_bin default null,
`dtl__capxrestart2` varchar(255) collate utf8_bin default null,
`dtl__capxuow` varchar(255) collate utf8_bin default null,
`dtl__capxuser` varchar(255) collate utf8_bin default null,
`dtl__capxtimestamp` varchar(20) collate utf8_bin default null,
`dtl__capxaction` varchar(1) collate utf8_bin default null,
`dtl__capxcasdelind` varchar(1) collate utf8_bin default null,
`dtl__capxrrn` decimal(10,0) default null,
`inserttime` timestamp ,
`updatetime` timestamp ,
`srcsys` varchar(10) collate utf8_bin default null,
primary key (`co`,`polnum`,`lstupdtime`)
) engine=innodb default charset=utf8 collate=utf8_bin

发现以下问题：

  • 与之前在源库SHOW CREATE TABLE的SQL不一致
  • lstupdtime 字段属性有 default null，但后面又被包含在primary key中（引起 1171 报错）
  • 与源库在 binlog 获取 CREATE TABLE 的SQL一致

产生以下推测：

  • SHOW CREATE TABLE的SQL是系统修正后的“正规”SQL
  • binlog拿到的SQL是人为输入的“原生”SQL
  • “原生”SQL在源库建表成功，在目标库执行失败，可能是版本差异引起的
    验证版本差异：

5.6 → 成功创建

5.7 → 报错 ERROR 1171

结论

  • 建表语句不规范，导致DTS链路故障

  • 在MySQL 5.6 中，当设计表时 datetime 数据类型的字段带有 default null，且设置为主键时，MySQL会自动将 default null 更正为 not null default ‘0000-00-00 00:00:00’，以满足 PRIMARY KEY 的需求

  • 在MySQL 5.7 中，当设计表时 datetime 数据类型的字段带有 default null，且设置为主键时，MySQL遵照用户的需求（default null），与 PRIMARY KEY 冲突，因此报错 1171

测试用例

—MySQL 5.6—

SQL中字段属性（并设置为主键） 结果 SHOW CREATE TABLE
col_test datetime(6) 建表成功 col_test datetime(6) NOT NULL DEFAULT ‘0000-00-00 00:00:00.000000’
col_test datetime(6) default null 建表成功 col_test datetime(6) NOT NULL DEFAULT ‘0000-00-00 00:00:00.000000’
col_test datetime(6) not null 建表成功 col_test datetime(6) NOT NULL

—MySQL 5.7—

SQL中字段属性（并设置为主键） 结果 SHOW CREATE TABLE
col_test datetime(6) 建表成功 col_test datetime(6) NOT NULL
col_test datetime(6) default null 建表失败 ERROR 1171
col_test datetime(6) not null 建表成功 col_test datetime(6) NOT NULL

知识延伸

explicit_defaults_for_timestamp 参数

  • 该参数只限制 timestamp 数据类型，对 datetime 无法起到限制作用
  • MySQL 5.6 需要在配置文件中修改该参数，重启服务后生效
  • MySQL 5.7 可直接修改该参数
explicit_defaults_for_timestamp SQL中字段属性 SHOW CREATE TABLE
OFF / 0 col01 timestamp col02 timestamp col01 timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP col01 timestamp NOT NULL DEFAULT ‘0000-00-00 00:00:00’
ON / 1 col01 timestamp col02 timestamp col01 timestamp NULL DEFAULT NULL col01 timestamp NULL DEFAULT NULL

解决方案

  • 由于同步链路“卡死”在当前这个建表的事务
  • 因此需要将该库从同步链路中移除，然后将整库重新加入到同步链路中
  • 阿里方虽然可以通过后台跳过该DDL，但有风险（可能跳过不止一个DDL）

思考

  • 如何普及研发人员操作数据库的规范？

  • 正确的互联网发布流程怎样才可以避免此类问题？