MySQL唯 一键约束场景下却能插入重复行？

时间：2021-11-15 00:56:18

1 、故障描述

某次，用户的一套 MySQL从库在同步时出现写入冲突报错。通过检查从库的错误日志信息，可以很清晰的发现报错共有两处，先是写入冲突报错，用户选择跳过该冲突事务之后，又碰到了删除报错。通过查看从库的binlog日志可以发现从库并不存在写入的重复行数据，那从库的第一个报错又从何而来呢。

2022-07-07 05:39:22 154606 [ERROR] Slave SQL: Could not execute Write_rows event on table zntj_gg.t_ius_user_sub_service; Duplicate entry '03254A7657C525984A2BB-aaa_001_86_3_5_1_1_gcw2-fitness' for key 'std_id', Error_code: 1062; handler error HA_ERR_FOUND_DUPP_KEY; the event's master log mysql-bin.004166, end_log_pos 255398155, Error_code: 1062
2022-07-07 05:39:22 154606 [Warning] Slave: Duplicate entry '03254A7657C525984A2BB-aaa_001_86_3_5_1_1_gcw2-fitness' for key 'std_id' Error_code: 1062
2022-07-07 05:39:22 154606 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.004166' position 255397852
2022-07-07 09:27:32 154606 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
2022-07-07 09:27:32 154606 [Note] Slave I/O thread killed while reading event
2022-07-07 09:27:32 154606 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.004167', position 58828583
2022-07-07 09:29:30 154606 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2022-07-07 09:29:30 154606 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2022-07-07 09:29:30 154606 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.004166' at position 255397852, relay log './mysqld-relay-bin.006839' position: 255398015
2022-07-07 09:29:30 154606 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398015', master_log_name='mysql-bin.004166', master_log_pos='255397852' and new position at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398349', master_log_name='mysql-bin.004166', master_log_pos='255398186' 
2022-07-07 09:29:30 154606 [Note] Slave I/O thread: connected to master 'replicauser@125.210.102.17:3306',replication started in log 'mysql-bin.004167' at position 58828583
2022-07-07 09:29:30 154606 [ERROR] Slave SQL: Could not execute Delete_rows event on table zntj_gg.t_ius_user_sub_service; Can't find record in 't_ius_user_sub_service', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql-bin.004166, end_log_pos 255398594, Error_code: 1032
2022-07-07 09:29:30 154606 [Warning] Slave: Can't find record in 't_ius_user_sub_service' Error_code: 1032
2022-07-07 09:29:30 154606 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.004166' position 255398186
2022-07-07 09:36:27 154606 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
2022-07-07 09:36:27 154606 [Note] Slave I/O thread killed while reading event
2022-07-07 09:36:27 154606 [Note] Slave I/O thread exiting, read up to log 'mysql-bin.004167', position 84764060
2022-07-07 09:37:05 154606 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2022-07-07 09:37:05 154606 [Note] Slave I/O thread: connected to master 'replicauser@125.210.102.17:3306',replication started in log 'mysql-bin.004167' at position 84764060
2022-07-07 09:37:05 154606 [Warning] Slave SQL: If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2022-07-07 09:37:05 154606 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.004166' at position 255398186, relay log './mysqld-relay-bin.006839' position: 255398349
2022-07-07 09:37:05 154606 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398349', master_log_name='mysql-bin.004166', master_log_pos='255398186' and new position at relay_log_file='./mysqld-relay-bin.006839', relay_log_pos='255398788', master_log_name='mysql-bin.004166', master_log_pos='255398625'

 

2 、根因分析

通过报错信息，检查相关表建表语句，怀疑当时从库是因为唯 一键冲突进而产生报错，然后用户选择使用 SQL_SLAVE_SKIP_COUNTER跳过该事务，使该数据未能写入，导致后面的delete事务无法找到匹配的行。

| t_ius_user_sub_service | CREATE TABLE `t_ius_user_sub_service` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `createTime` datetime DEFAULT NULL,
  `lastUpdateTime` datetime DEFAULT NULL,
  `status` bigint(20) DEFAULT NULL,
  `cust_code` varchar(255) DEFAULT NULL,
  `std_id` varchar(255) DEFAULT NULL,
  `sub_service_code` varchar(255) DEFAULT NULL,
  `serviceType` varchar(255) DEFAULT NULL,
  `watchnum` int(11) NOT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `std_id` (`std_id`,`sub_service_code`,`serviceType`) USING BTREE,
  KEY `sub_service_code` (`sub_service_code`) USING BTREE
) ENGINE=InnoDB AUTO_INCREMENT=2913132 DEFAULT CHARSET=utf8


很快，通过解析主库的 binlog日志，得到了确实的证据，在主库的binlog日志中，可以看到先是插入了两条语句，然后通过delete删除了这两条语句。那么问题来了，这两条插入的语句，根据建表语句中的设置，应该是会产生唯 一键冲突的，为什么从库执行失败报错了，主库却能顺利执行呢？

# at 255397487
#220707  5:39:22 server id 10261  end_log_pos 255397518 CRC32 0xea016589  Xid = 270516762358
COMMIT/*!*/;
# at 255397518
#220707  5:39:22 server id 10261  end_log_pos 255397593 CRC32 0x6f5eeff0  Query thread_id=172971976 exec_time=0    error_code=0
SET TIMESTAMP=1657143562/*!*/;
BEGIN
/*!*/;
# at 255397593
#220707  5:39:22 server id 10261  end_log_pos 255397680 CRC32 0x40ae4e57  Table_map: `zntj_gg`.`t_ius_user_sub_service` mapped to number 270345775
# at 255397680
#220707  5:39:22 server id 10261  end_log_pos 255397821 CRC32 0x8658dd38  Write_rows: table id 270345775 flags: STMT_END_F
### INSERT INTO `zntj_gg`.`t_ius_user_sub_service`
### SET
###   @1=2912517
###   @2='2022-07-07 05:39:18'
###   @3='2022-07-07 05:39:18'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
# at 255397821
#220707  5:39:22 server id 10261  end_log_pos 255397852 CRC32 0x78e79f44  Xid = 270516762129
COMMIT/*!*/;
# at 255397852
#220707  5:39:22 server id 10261  end_log_pos 255397927 CRC32 0x7833f5aa  Query thread_id=172587714 exec_time=0    error_code=0
SET TIMESTAMP=1657143562/*!*/;
BEGIN
/*!*/;
# at 255397927
#220707  5:39:22 server id 10261  end_log_pos 255398014 CRC32 0xba4235b0  Table_map: `zntj_gg`.`t_ius_user_sub_service` mapped to number 270345775
# at 255398014
#220707  5:39:22 server id 10261  end_log_pos 255398155 CRC32 0xe772beb9  Write_rows: table id 270345775 flags: STMT_END_F
### INSERT INTO `zntj_gg`.`t_ius_user_sub_service`
### SET
###   @1=2912518
###   @2='2022-07-07 05:38:38'
###   @3='2022-07-07 05:38:38'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
# at 255398155
#220707  5:39:22 server id 10261  end_log_pos 255398186 CRC32 0x1e02a19d  Xid = 270516762223
COMMIT/*!*/;
# at 255398186
#220707  5:36:36 server id 10261  end_log_pos 255398261 CRC32 0x0080cbe2  Query thread_id=149724384 exec_time=166  error_code=0
SET TIMESTAMP=1657143396/*!*/;
BEGIN
/*!*/;
# at 255398261
#220707  5:36:36 server id 10261  end_log_pos 255398348 CRC32 0xb2c4244c  Table_map: `zntj_gg`.`t_ius_user_sub_service` mapped to number 270345775
# at 255398348
#220707  5:36:36 server id 10261  end_log_pos 255398594 CRC32 0xc964c586  Delete_rows: table id 270345775 flags: STMT_END_F
### DELETE FROM `zntj_gg`.`t_ius_user_sub_service`
### WHERE
###   @1=2912517
###   @2='2022-07-07 05:39:18'
###   @3='2022-07-07 05:39:18'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
### DELETE FROM `zntj_gg`.`t_ius_user_sub_service`
### WHERE
###   @1=2912518
###   @2='2022-07-07 05:38:38'
###   @3='2022-07-07 05:38:38'
###   @4=0
###   @5='33040120001443'
###   @6='03254A7657C525984A2BB'
###   @7='aaa_001_86_3_5_1_1_gcw2'
###   @8='fitness'
###   @9=0
# at 255398594
#220707  5:39:22 server id 10261  end_log_pos 255398625 CRC32 0xd01c4287  Xid = 270512016580
COMMIT/*!*/;


排查到这一步，不觉的陷入了沉思，在唯 一键约束存在的前提下，居然能插入重复行？？？难道，该约束被禁用了？首先，尝试在常规情况下主库能插入两条唯 一键冲突数据的办法。方式 1：通过设置unique_checks参数为0来关闭数据库的唯 一键检查。方式2：可以修改插入语句，通过insert ignore、replace into、insert on duplicate key update三种手段来规避唯 一键冲突。然而，实际情况unique_checks参数为1，且业务执行语句时并未修改unique_checks参数。而通过binlog日志的记录可以发现，当时确实是有两个数据插入成功，与insert ignore、replace into、insert on duplicate key update这些手段的规避结果不同。

分析到这里还没有确切的证据，我们便需要模拟环境，尝试对报错的场景进行复现，通过分析主库的 binlog日志，我们可以发现，delete事务是在5:36:36开始执行，然后和两个insert事务一起在5:39:22结束。模拟实际环境数据库的版本和配置文件，创建一个和原库配置相同的数据库来进行场景复现。

  MySQL唯 一键约束场景下却能插入重复行？

然后开启四个窗口，第一个窗口加持锁，然后第二个窗口对表进行 delete操作，然后第三个窗口和第四个窗口准备好insert语句，最后根据binlog记录依次执行。先执行insert语句，然后解锁执行delete语句，尽量保持在较短时间内执行，以模拟场景中的同时进行。

  MySQL唯 一键约束场景下却能插入重复行？

  MySQL唯 一键约束场景下却能插入重复行？

最后通过几轮测试会发现，模拟的结果与实际报错场景不同，在测试中，插入唯 一键冲突的数据会报错。说明实际场景中出现的情况是不合逻辑的，不常见的。

此时，相信很多朋友会纳闷，那是不是碰到 MySQL  BUG 了。怀揣着同样的想法，笔者去 MySQL  BUG 网站捞了一把，幸运的发现了新的收获，确实存在类似的 B UG ，如下：

  MySQL唯 一键约束场景下却能插入重复行？

详情可以参考：

3 、解决方案

为了防止业务表上出现不必要的重复行，或者避免数据错乱，建议将当前 MySQL升级至当前系列的最新小版本或直接升级到高版本。

 


相关文章