案件回顾
- 一条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 解析结果
SQL: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=noSET @@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=0use `cds`/*!*/;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=0SET 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 'PJbEXhPpg8yHqgAAAOQ9iQAAAFIFAAAAAAEADGlzcF9tYWluZGJfcwAMc3lzX3VzZXJpbmZvACoIDw8PDw8PDw8PDw8SDw8DAwMDDxISCPwSAw8PEhIPDw8SEg8PDw8PDw89YAADAAMA7gIwADAANgAYAFgCYABgAAADAIABAwAAAAIAlgBgAAAA/QJYAlgCAAAeAP0C/QL9Av0CPAADAP7/AwRlIl0=PJbEXhnpg8yHaQIAAE1AiQAAAFIFAAAAAAMAKv///8BYAACA/LEIAAAAAAAACTAwMDAxNjk3MQFBATEhAOacseWLpOWNjiAgICAgICAgICAgICAgICAgICAgICAgIAROVUxMBDA5ODYEAEZFMDEJRzAwMDAwNDA5ATABAAAAAQAAAAEAAAABAAAAAUGZpG4AAJmknQSyAAAAAAAAAADKAHtBU0lUVTpDTSxFQUZDUjowMDAwMDM0MjEsQ0hBTk5FTDpBZ2VuY3l9LXsiQUdUQ09EIjoiMDAwMDE2OTcxICAgICIsIk9GRkNPRCI6IkZFMDEiLCJBR1lDT0QiOiJHMDAwMDA0MDkiLCJyb3dfbnVtYmVyIjo5NSwiQ09OVFlQRSI6Ik0xIiwiaW5pUHdkIjoiMTExMTExMTEiLCJBR1ROQU1FIjoi5pyx5Yuk5Y2OICAgICAgICAgICAgICAgICAgICAgICAgIn2ZpgcaagAAAAAGQWdlbmN5CDExMDMwNTM3mZ3lBKiZpmillAIAQ00IADExMTExMTExGABSWU96dm9Vd3JiaEJBeWwxNnhxLzRRPT2ZpmimRpmmaKZGA0lTUEwAMDdFNDAwMDUwMDE0MDAwQTAwMTYwMDE2MEI4MEYyNDAwMDAwMDAxRDAwMDBBRkI0MDAwMDM0MUEwMDA2MDAwMDAwMDEwMDAwMDAwMCIAOTIwMDAwMDA0MzQ4NEY1NDMzNTIzODQzNTM1MTRDMzEzMRQAMDAwMEFGQjQwMDAwMzQxQTAwMDYUMjAyMDA1MjAxMDIyMjIxOTMwMDABSe7KpkM='/*!*/;### DELETE FROM `i_s`.`sys_userinfo`### WHERE### @1=2225 /* LONGINT meta=0 nullable=0 is_null=0 */
发现SQL:DROP TABLE IF EXISTS plog /* generated by server */
执行时间:200520 10:30:11
由于该DROP动作,无论库中是否存在该表,binlog均会记录,因此想何时该DROP动作在建表之后
从源库information_schema.tables获取表的创建时间
![ec1266ee7462798f5ac9476ae09bf63b.png](https://img-blog.csdnimg.cn/img_convert/ec1266ee7462798f5ac9476ae09bf63b.png)
与DROP的时间一致
因后来证实,当 alter 表示,create_time 字段会被更新;增删改查表时,update_time字段会被更新;truncate表示,时间字段不被更新
因此怀疑该时间不够准确,决定从PolarDB获取对应时间段的binlog日志,查看该时间是否是CREATE TABLE的时间
由于PolarDB不支持直接下载binlog需要通过客户端连接的方式把binlog日志解析到本地
通过客户端连接获取binlog的命令
shell: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 解析结果
SQL:# at 398730036#200520 10:30:10 server id 9793953 end_log_pos 398730084 CRC32 0x42791024 GTID last_committed=0 sequence_number=0SET @@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=0use `cds`/*!*/;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=0SET @@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=0SET 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 `lstupdtime` datetime(6) 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=0SET @@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=0SET 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 `i_s`.`sys_userinfo`### WHERE### @1=2225 /* LONGINT meta=0 nullable=0 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
SQL:mysql>show create table plogG*************************** 1. row *************************** Table: plogCreate Table: CREATE TABLE `plog` ( `co` varchar(4) COLLATE utf8_bin NOT NULL DEFAULT '', `polnum` varchar(10) COLLATE utf8_bin NOT NULL DEFAULT '', `lstupdtime` datetime(6) NOT NULL DEFAULT '0000-00-00 00:00:00.000000', `inserttime` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP, `updatetime` timestamp NOT NULL DEFAULT '0000-00-00 00:00:00', PRIMARY KEY (`co`,`polnum`,`lstupdtime`)) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_bin返回行数:[1],耗时:6 ms.
将该建表语句复制到目标端手动创建,然后启动DTS链路
再通过SELECT * FROM 表 来验证数据是否正常同步过来时,提示该表不存在
刷新DTS链路信息,DTS链路报错,报错与之前一致
多次重复上述操作,均可复现,现象反馈给阿里方,协助排查该问题
阶段四:开启审计,查找“真凶”
- 在阿里方的建议下,开启审计,查看是“谁”删除了这张表
审计内容
提示通过审计内容查看:
2020-05-21 10:28:39.885 create 失败
2020-05-21 10:28:39: 791 drop 成功
发现是eds_dev用户,是 DTS 同步用户,传输过来的动作是先进行 DROP 再进行创建,但创建失败
CREATE 之前先 DROP,就是手动创建被会失败的原因
而 CREATE 之所以失败,根据审计的提示,失败代码:1171
查询 MySQL 的错误代码 1171
![b60e83757b3b5a5bfa17a862ff6482a4.png](https://img-blog.csdnimg.cn/img_convert/b60e83757b3b5a5bfa17a862ff6482a4.png)
当主键的字段属性为“允许空值”时会报出1171的错误代码
检查审计 CREATE TABLE 语句
SQL:---目标库 CREATE TABLE 语句---create table `cds`.`plog`( `co` varchar(4) collate utf8_bin not null default '',`polnum` varchar(10) collate utf8_bin not null default '',`lstupdtime` datetime(6) default null,`inserttime` timestamp ,`updatetime` timestamp ,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
![8eb970424c1bb6e0145d489691d94dbd.png](https://img-blog.csdnimg.cn/img_convert/8eb970424c1bb6e0145d489691d94dbd.png)
结论
- 建表语句不规范,导致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
测试用例
![65de3babd1d6ed15ddcddababe40042d.png](https://img-blog.csdnimg.cn/img_convert/65de3babd1d6ed15ddcddababe40042d.png)
知识延伸
explicit_defaults_for_timestamp 参数
- 该参数只限制 timestamp 数据类型,对 datetime 无法起到限制作用
- MySQL 5.6 需要在配置文件中修改该参数,重启服务后生效
- MySQL 5.7 可直接修改该参数
![29594a558d37bbc27eca5596d3cb6da0.png](https://img-blog.csdnimg.cn/img_convert/29594a558d37bbc27eca5596d3cb6da0.png)
解决方案
- 由于同步链路“卡死”在当前这个建表的事务
- 因此需要将该库从同步链路中移除,然后将整库重新加入到同步链路中
- 阿里方虽然可以通过后台跳过该DDL,但有风险(可能跳过不止一个DDL)
思考
- 如何普及研发人员操作数据库的规范?
- 正确的互联网发布流程怎样才可以避免此类问题?
本文分享内容是我自己的一些见解,欢迎大家一起来评论留言探讨,我会不定期更新内容,大家可以关注我哟~